2021-09-22 10:39:13,880+0100 INFO (jsonrpc/0) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=16cf6f3d-a87f-4165-a07f-d41f6f9b9175 (api:48) 2021-09-22 10:39:13,881+0100 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.9', 'delay': '0.000471624', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=16cf6f3d-a87f-4165-a07f-d41f6f9b9175 (api:54) 2021-09-22 10:39:14,507+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33470 (protocoldetector:61) 2021-09-22 10:39:14,514+0100 WARN (Reactor thread) [vds.dispatcher] unhandled write event (betterAsyncore:184) 2021-09-22 10:39:14,514+0100 INFO (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from 127.0.0.1:33470 (protocoldetector:125) 2021-09-22 10:39:14,515+0100 INFO (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompserver:95) 2021-09-22 10:39:14,516+0100 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompserver:124) 2021-09-22 10:39:14,993+0100 INFO (jsonrpc/4) [vdsm.api] START getSpmStatus(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38252, task_id=30be11cd-e901-4db7-8bd5-cb71e8ff39ac (api:48) 2021-09-22 10:39:14,996+0100 INFO (jsonrpc/4) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmStatus': 'SPM', 'spmLver': 28, 'spmId': 8}} from=10.187.21.239,38252, task_id=30be11cd-e901-4db7-8bd5-cb71e8ff39ac (api:54) 2021-09-22 10:39:15,001+0100 INFO (jsonrpc/5) [vdsm.api] START getStoragePoolInfo(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38276, task_id=83c9e302-b093-4016-b1bd-63076e6ac5ac (api:48) 2021-09-22 10:39:15,004+0100 INFO (jsonrpc/5) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'domains': 'e2627376-2254-4e90-9478-0223ef873214:Active,176ed26c-5e20-4b2d-ab10-855f519e0b0f:Active,a7ed0992-91f6-4236-8e18-29c5def2c845:Active', 'isoprefix': '', 'lver': 28, 'master_uuid': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'master_ver': 1, 'name': 'No Description', 'pool_status': 'connected', 'spm_id': 8, 'type': 'ISCSI', 'version': '5'}, 'dominfo': {'e2627376-2254-4e90-9478-0223ef873214': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '778107871232', 'diskfree': '740668747776'}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '1610210082816', 'diskfree': '528817848320'}, 'a7ed0992-91f6-4236-8e18-29c5def2c845': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '106971529216', 'diskfree': '18119393280'}}} from=10.187.21.239,38276, task_id=83c9e302-b093-4016-b1bd-63076e6ac5ac (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:15,525::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call dmsetup_run_status with ('multipath',) {} MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:15,525::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/dmsetup status --target multipath (cwd None) MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:15,539::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:15,540::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return dmsetup_run_status with b'36001405793765d9df7abd4849da87bdc: 0 4123000832 multipath 2 0 1 0 2 1 A 0 1 2 8:32 A 0 0 1 E 0 1 2 8:16 A 0 0 1 \n36001405534d4874d3b27d4d1cd86a0d0: 0 3145728000 multipath 2 0 1 0 2 1 A 0 1 2 8:96 A 0 0 1 E 0 1 2 8:80 A 0 0 1 \n36001405534d48dbda440d4f9bd8c15df: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:64 A 0 0 1 E 0 1 2 8:48 A 0 0 1 \n' ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:16,516+0100 WARN (JsonRpc (StompReactor)) [vds.dispatcher] unhandled close event (betterAsyncore:184) 2021-09-22 10:39:16,517+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33472 (protocoldetector:61) 2021-09-22 10:39:16,576+0100 INFO (jsonrpc/2) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=c2bcbf7a-3721-4c60-a743-d300f4d48269 (api:48) 2021-09-22 10:39:16,576+0100 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '7.6', 'delay': '0.000471624', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=c2bcbf7a-3721-4c60-a743-d300f4d48269 (api:54) 2021-09-22 10:39:18,348+0100 INFO (jsonrpc/3) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:39:18,351+0100 INFO (jsonrpc/3) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192834196', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173633', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '55.75', 'cpuSys': '15.47', 'cpuUsage': '8043460000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514048637', 'tx': '82925630', 'sampleTime': 45350.550354336}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '793277.0', 'writeLatency': '587810.3833333333', 'flushLatency': '208298.2037037037', 'writtenBytes': '2814301184', 'writeOps': '218972', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '1365.3225992583073', 'writeRate': '39594.35537849091', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9286704', 'mem_free': '10326368', 'swap_in': 0, 'swap_out': 0, 'majflt': 0, 'minflt': 45, 'pageflt': 45}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '38', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) 2021-09-22 10:39:18,992+0100 INFO (jsonrpc/1) [api.host] START getAllVmStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:39:18,993+0100 INFO (jsonrpc/1) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=10.187.21.239,38252 (api:54) 2021-09-22 10:39:19,048+0100 INFO (jsonrpc/0) [api.host] START getStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:39:19,067+0100 INFO (jsonrpc/0) [vdsm.api] START repoStats(domains=()) from=10.187.21.239,38252, task_id=f636b6a3-ad36-4b52-a496-25343c3d2f7e (api:48) 2021-09-22 10:39:19,068+0100 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '0.1', 'delay': '0.000575566', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '5.4', 'delay': '0.00239462', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '0.6', 'delay': '0.000474789', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=10.187.21.239,38252, task_id=f636b6a3-ad36-4b52-a496-25343c3d2f7e (api:54) 2021-09-22 10:39:19,068+0100 INFO (jsonrpc/0) [vdsm.api] START multipath_health() from=10.187.21.239,38252, task_id=cfca737c-7465-4e48-bde3-1f92d6879595 (api:48) 2021-09-22 10:39:19,068+0100 INFO (jsonrpc/0) [vdsm.api] FINISH multipath_health return={} from=10.187.21.239,38252, task_id=cfca737c-7465-4e48-bde3-1f92d6879595 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:19,070 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:19,071 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:19,081+0100 INFO (jsonrpc/0) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=10.187.21.239,38252 (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/4::DEBUG::2021-09-22 10:39:19,229::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call tasksList with ([],) {} MainProcess|jsonrpc/4::DEBUG::2021-09-22 10:39:19,229::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/gluster --mode=script volume status all tasks --xml (cwd None) MainProcess|jsonrpc/4::DEBUG::2021-09-22 10:39:19,326::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|jsonrpc/4::DEBUG::2021-09-22 10:39:19,327::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return tasksList with {} ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:21,482+0100 INFO (jsonrpc/5) [api.host] START getAllVmStats() from=127.0.0.1,40080 (api:48) 2021-09-22 10:39:21,483+0100 INFO (jsonrpc/5) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=127.0.0.1,40080 (api:54) 2021-09-22 10:39:21,499+0100 INFO (jsonrpc/6) [api.host] START getAllVmIoTunePolicies() from=127.0.0.1,40080 (api:48) 2021-09-22 10:39:21,499+0100 INFO (jsonrpc/6) [api.host] FINISH getAllVmIoTunePolicies return={'status': {'code': 0, 'message': 'Done'}, 'io_tune_policies_dict': {'21a5b48e-218a-48ba-bf8e-60451f4d1793': {'policy': [], 'current_values': [{'name': 'vda', 'path': '/run/vdsm/storage/a7ed0992-91f6-4236-8e18-29c5def2c845/a3333af7-6967-4342-8f14-cf6f8924cd9d/f6f8d017-354f-466d-bc03-0b2d4a30dd63', 'ioTune': {'total_bytes_sec': 0, 'read_bytes_sec': 0, 'write_bytes_sec': 0, 'total_iops_sec': 0, 'write_iops_sec': 0, 'read_iops_sec': 0}}]}}} from=127.0.0.1,40080 (api:54) 2021-09-22 10:39:23,258+0100 INFO (jsonrpc/3) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:23,291+0100 INFO (jsonrpc/3) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=095a2b46-567a-4029-8a0e-c180990d6a23 (api:48) 2021-09-22 10:39:23,292+0100 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.3', 'delay': '0.000575566', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.0', 'delay': '0.00219207', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.8', 'delay': '0.000474789', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=095a2b46-567a-4029-8a0e-c180990d6a23 (api:54) 2021-09-22 10:39:23,292+0100 INFO (jsonrpc/3) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=7be412a2-1176-4dd8-9716-db91664cf9f3 (api:48) 2021-09-22 10:39:23,293+0100 INFO (jsonrpc/3) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=7be412a2-1176-4dd8-9716-db91664cf9f3 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:23,295 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:23,297 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:23,302+0100 INFO (jsonrpc/0) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:23,334+0100 INFO (jsonrpc/0) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=09f3f6c0-b81b-4b8a-b68a-361b7dda3465 (api:48) 2021-09-22 10:39:23,335+0100 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.3', 'delay': '0.000575566', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.0', 'delay': '0.00219207', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.8', 'delay': '0.000474789', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=09f3f6c0-b81b-4b8a-b68a-361b7dda3465 (api:54) 2021-09-22 10:39:23,335+0100 INFO (jsonrpc/0) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=932f5ec1-a577-4e03-b537-7ec8243aa4fb (api:48) 2021-09-22 10:39:23,336+0100 INFO (jsonrpc/0) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=932f5ec1-a577-4e03-b537-7ec8243aa4fb (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:23,337 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:23,339 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:23,348+0100 INFO (jsonrpc/3) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:23,354+0100 INFO (jsonrpc/0) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:23,986+0100 INFO (jsonrpc/6) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=b8eb0200-44fa-4562-b165-d31a0f269f21 (api:48) 2021-09-22 10:39:23,986+0100 INFO (jsonrpc/6) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.0', 'delay': '0.000575566', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=b8eb0200-44fa-4562-b165-d31a0f269f21 (api:54) 2021-09-22 10:39:25,018+0100 INFO (jsonrpc/2) [vdsm.api] START getSpmStatus(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38252, task_id=7af298cd-47a3-49c8-9782-bcc2ed3619a1 (api:48) 2021-09-22 10:39:25,021+0100 INFO (jsonrpc/2) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmStatus': 'SPM', 'spmLver': 28, 'spmId': 8}} from=10.187.21.239,38252, task_id=7af298cd-47a3-49c8-9782-bcc2ed3619a1 (api:54) 2021-09-22 10:39:25,026+0100 INFO (jsonrpc/7) [vdsm.api] START getStoragePoolInfo(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38276, task_id=4d09949c-e2ec-4ede-8f57-364ec1632ffb (api:48) 2021-09-22 10:39:25,029+0100 INFO (jsonrpc/7) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'domains': 'e2627376-2254-4e90-9478-0223ef873214:Active,176ed26c-5e20-4b2d-ab10-855f519e0b0f:Active,a7ed0992-91f6-4236-8e18-29c5def2c845:Active', 'isoprefix': '', 'lver': 28, 'master_uuid': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'master_ver': 1, 'name': 'No Description', 'pool_status': 'connected', 'spm_id': 8, 'type': 'ISCSI', 'version': '5'}, 'dominfo': {'e2627376-2254-4e90-9478-0223ef873214': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '778107871232', 'diskfree': '740668747776'}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '1610210082816', 'diskfree': '528817848320'}, 'a7ed0992-91f6-4236-8e18-29c5def2c845': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '106971529216', 'diskfree': '18119393280'}}} from=10.187.21.239,38276, task_id=4d09949c-e2ec-4ede-8f57-364ec1632ffb (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:25,540::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call dmsetup_run_status with ('multipath',) {} MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:25,540::logutils::354::root::(_report_stats) ThreadedHandler is ok in the last 60 seconds (max pending: 2) MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:25,541::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/dmsetup status --target multipath (cwd None) MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:25,551::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:25,551::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return dmsetup_run_status with b'36001405793765d9df7abd4849da87bdc: 0 4123000832 multipath 2 0 1 0 2 1 A 0 1 2 8:32 A 0 0 1 E 0 1 2 8:16 A 0 0 1 \n36001405534d4874d3b27d4d1cd86a0d0: 0 3145728000 multipath 2 0 1 0 2 1 A 0 1 2 8:96 A 0 0 1 E 0 1 2 8:80 A 0 0 1 \n36001405534d48dbda440d4f9bd8c15df: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:64 A 0 0 1 E 0 1 2 8:48 A 0 0 1 \n' ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:26,529+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33476 (protocoldetector:61) 2021-09-22 10:39:26,536+0100 WARN (Reactor thread) [vds.dispatcher] unhandled write event (betterAsyncore:184) 2021-09-22 10:39:26,536+0100 INFO (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from 127.0.0.1:33476 (protocoldetector:125) 2021-09-22 10:39:26,536+0100 INFO (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompserver:95) 2021-09-22 10:39:26,537+0100 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompserver:124) 2021-09-22 10:39:26,591+0100 INFO (jsonrpc/3) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=00f65269-86d1-4d70-ac6d-4a64c0e1fe59 (api:48) 2021-09-22 10:39:26,591+0100 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '7.6', 'delay': '0.000575566', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=00f65269-86d1-4d70-ac6d-4a64c0e1fe59 (api:54) 2021-09-22 10:39:27,439+0100 INFO (periodic/1) [vdsm.api] START repoStats(domains=()) from=internal, task_id=45b64975-99e0-4a7b-a1b9-83714ea7d2fa (api:48) 2021-09-22 10:39:27,439+0100 INFO (periodic/1) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '8.4', 'delay': '0.000575566', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.8', 'delay': '0.00219207', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '3.9', 'delay': '0.000474789', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=internal, task_id=45b64975-99e0-4a7b-a1b9-83714ea7d2fa (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:27,456 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:27,470 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:28,480+0100 INFO (jsonrpc/4) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:39:28,482+0100 INFO (jsonrpc/4) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192844328', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173643', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '55.71', 'cpuSys': '17.40', 'cpuUsage': '8046070000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514214456', 'tx': '82948325', 'sampleTime': 45360.68186528}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '0', 'writeLatency': '404310.3965517241', 'flushLatency': '192735.66666666666', 'writtenBytes': '2814829056', 'writeOps': '219030', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '0.0', 'writeRate': '35191.12667815803', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9286868', 'mem_free': '10326308', 'swap_in': 1, 'swap_out': 0, 'majflt': 0, 'minflt': 435, 'pageflt': 435}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '38', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) 2021-09-22 10:39:28,538+0100 WARN (JsonRpc (StompReactor)) [vds.dispatcher] unhandled close event (betterAsyncore:184) 2021-09-22 10:39:28,538+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33478 (protocoldetector:61) 2021-09-22 10:39:32,830+0100 INFO (jsonrpc/5) [api.storage] START attach_volume(vol_id='ed1a0e9f-4d30-4896-b965-534861cc0c02', connection_info={'driver_volume_type': 'iscsi', 'data': {'target_discovered': False, 'target_iqn': 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'target_portal': '10.187.21.238:3260', 'volume_id': 'ed1a0e9f-4d30-4896-b965-534861cc0c02', 'access_mode': 'rw', 'discard': False, 'target_portals': ['10.187.21.238:3260', '10.187.21.237:3260'], 'target_iqns': ['iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02'], 'target_lun': 0, 'target_luns': [0, 0]}}) from=10.187.21.239,38252, flow_id=7e0493eb (api:48) 2021-09-22 10:39:32,831+0100 INFO (jsonrpc/5) [storage.managevolumedb] Adding volume ed1a0e9f-4d30-4896-b965-534861cc0c02 connection_info={'driver_volume_type': 'iscsi', 'data': {'target_discovered': False, 'target_iqn': 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'target_portal': '10.187.21.238:3260', 'volume_id': 'ed1a0e9f-4d30-4896-b965-534861cc0c02', 'access_mode': 'rw', 'discard': False, 'target_portals': ['10.187.21.238:3260', '10.187.21.237:3260'], 'target_iqns': ['iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02'], 'target_lun': 0, 'target_luns': [0, 0]}} (managedvolumedb:181) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:32,848::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call managedvolume_run_helper with ('attach',) {'cmd_input': {'driver_volume_type': 'iscsi', 'data': {'target_discovered': False, 'target_iqn': 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'target_portal': '10.187.21.238:3260', 'volume_id': 'ed1a0e9f-4d30-4896-b965-534861cc0c02', 'access_mode': 'rw', 'discard': False, 'target_portals': ['10.187.21.238:3260', '10.187.21.237:3260'], 'target_iqns': ['iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02'], 'target_lun': 0, 'target_luns': [0, 0]}}} MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:32,848::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/bin/python3 /usr/libexec/vdsm/managedvolume-helper attach (cwd None) ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:33,366+0100 INFO (jsonrpc/2) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:33,385+0100 INFO (jsonrpc/2) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=8a24bc03-c97c-49fd-a77b-ca3c771932f6 (api:48) 2021-09-22 10:39:33,385+0100 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.4', 'delay': '0.000470956', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.1', 'delay': '0.00222521', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.9', 'delay': '0.000461749', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=8a24bc03-c97c-49fd-a77b-ca3c771932f6 (api:54) 2021-09-22 10:39:33,386+0100 INFO (jsonrpc/2) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=3dedc575-997c-47ad-ae33-9c1f9e9283f3 (api:48) 2021-09-22 10:39:33,386+0100 INFO (jsonrpc/2) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=3dedc575-997c-47ad-ae33-9c1f9e9283f3 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:33,388 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:33,389 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:33,396+0100 INFO (jsonrpc/2) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:33,404+0100 INFO (jsonrpc/1) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:33,423+0100 INFO (jsonrpc/1) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=d3064cc7-4f09-4284-9911-87f45e3bafbc (api:48) 2021-09-22 10:39:33,423+0100 INFO (jsonrpc/1) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.4', 'delay': '0.000470956', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.1', 'delay': '0.00222521', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.9', 'delay': '0.000461749', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=d3064cc7-4f09-4284-9911-87f45e3bafbc (api:54) 2021-09-22 10:39:33,423+0100 INFO (jsonrpc/1) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=13e6fd5b-59f7-4b62-852e-fa9159e1a0b5 (api:48) 2021-09-22 10:39:33,424+0100 INFO (jsonrpc/1) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=13e6fd5b-59f7-4b62-852e-fa9159e1a0b5 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:33,425 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:33,426 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:33,432+0100 INFO (jsonrpc/1) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:34,003+0100 INFO (jsonrpc/3) [api.host] START getAllVmStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:39:34,005+0100 INFO (jsonrpc/3) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=10.187.21.239,38252 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:34,082 - mom.RPCServer - INFO - ping() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:34,059+0100 INFO (jsonrpc/4) [api.host] START getStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:39:34,080+0100 INFO (jsonrpc/4) [vdsm.api] START repoStats(domains=()) from=10.187.21.239,38252, task_id=be7b17b2-4447-4174-963a-c465ec36e6b9 (api:48) 2021-09-22 10:39:34,080+0100 INFO (jsonrpc/4) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.1', 'delay': '0.000470956', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '0.4', 'delay': '0.00222521', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '0.6', 'delay': '0.000461749', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=10.187.21.239,38252, task_id=be7b17b2-4447-4174-963a-c465ec36e6b9 (api:54) 2021-09-22 10:39:34,080+0100 INFO (jsonrpc/4) [vdsm.api] START multipath_health() from=10.187.21.239,38252, task_id=ce753897-fbc2-4178-939d-94660db2366d (api:48) 2021-09-22 10:39:34,080+0100 INFO (jsonrpc/4) [vdsm.api] FINISH multipath_health return={} from=10.187.21.239,38252, task_id=ce753897-fbc2-4178-939d-94660db2366d (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:34,083 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:34,093+0100 INFO (jsonrpc/2) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=72fc2d2d-ac28-467a-88ea-a844080abb7d (api:48) 2021-09-22 10:39:34,093+0100 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.1', 'delay': '0.000470956', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=72fc2d2d-ac28-467a-88ea-a844080abb7d (api:54) 2021-09-22 10:39:34,095+0100 INFO (jsonrpc/4) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=10.187.21.239,38252 (api:54) 2021-09-22 10:39:35,046+0100 INFO (jsonrpc/7) [vdsm.api] START getSpmStatus(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38252, task_id=84503585-2dce-48a7-87be-db4c8eaecefa (api:48) 2021-09-22 10:39:35,050+0100 INFO (jsonrpc/7) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmStatus': 'SPM', 'spmLver': 28, 'spmId': 8}} from=10.187.21.239,38252, task_id=84503585-2dce-48a7-87be-db4c8eaecefa (api:54) 2021-09-22 10:39:35,090+0100 INFO (jsonrpc/1) [vdsm.api] START getStoragePoolInfo(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38276, task_id=a7ec5124-a259-4c0e-bc71-6cfc71a1e626 (api:48) 2021-09-22 10:39:35,094+0100 INFO (jsonrpc/1) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'domains': 'e2627376-2254-4e90-9478-0223ef873214:Active,176ed26c-5e20-4b2d-ab10-855f519e0b0f:Active,a7ed0992-91f6-4236-8e18-29c5def2c845:Active', 'isoprefix': '', 'lver': 28, 'master_uuid': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'master_ver': 1, 'name': 'No Description', 'pool_status': 'connected', 'spm_id': 8, 'type': 'ISCSI', 'version': '5'}, 'dominfo': {'e2627376-2254-4e90-9478-0223ef873214': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '778107871232', 'diskfree': '740668747776'}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '1610210082816', 'diskfree': '528817848320'}, 'a7ed0992-91f6-4236-8e18-29c5def2c845': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '106971529216', 'diskfree': '18119393280'}}} from=10.187.21.239,38276, task_id=a7ec5124-a259-4c0e-bc71-6cfc71a1e626 (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:35,552::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call dmsetup_run_status with ('multipath',) {} MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:35,552::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/dmsetup status --target multipath (cwd None) MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:35,569::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:35,569::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return dmsetup_run_status with b'360014054b727813d1bc4d4cefdade7db: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:112 A 0 0 1 E 0 1 2 8:128 A 0 0 1 \n36001405793765d9df7abd4849da87bdc: 0 4123000832 multipath 2 0 1 0 2 1 A 0 1 2 8:32 A 0 0 1 E 0 1 2 8:16 A 0 0 1 \n36001405534d4874d3b27d4d1cd86a0d0: 0 3145728000 multipath 2 0 1 0 2 1 A 0 1 2 8:96 A 0 0 1 E 0 1 2 8:80 A 0 0 1 \n36001405534d48dbda440d4f9bd8c15df: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:64 A 0 0 1 E 0 1 2 8:48 A 0 0 1 \n' ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:36,489+0100 INFO (jsonrpc/3) [api.host] START getAllVmStats() from=127.0.0.1,40080 (api:48) 2021-09-22 10:39:36,491+0100 INFO (jsonrpc/3) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=127.0.0.1,40080 (api:54) 2021-09-22 10:39:36,516+0100 INFO (jsonrpc/0) [api.host] START getAllVmIoTunePolicies() from=127.0.0.1,40080 (api:48) 2021-09-22 10:39:36,516+0100 INFO (jsonrpc/0) [api.host] FINISH getAllVmIoTunePolicies return={'status': {'code': 0, 'message': 'Done'}, 'io_tune_policies_dict': {'21a5b48e-218a-48ba-bf8e-60451f4d1793': {'policy': [], 'current_values': [{'name': 'vda', 'path': '/run/vdsm/storage/a7ed0992-91f6-4236-8e18-29c5def2c845/a3333af7-6967-4342-8f14-cf6f8924cd9d/f6f8d017-354f-466d-bc03-0b2d4a30dd63', 'ioTune': {'total_bytes_sec': 0, 'read_bytes_sec': 0, 'write_bytes_sec': 0, 'total_iops_sec': 0, 'write_iops_sec': 0, 'read_iops_sec': 0}}]}}} from=127.0.0.1,40080 (api:54) 2021-09-22 10:39:36,605+0100 INFO (jsonrpc/2) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=9e9cdb19-c502-4c26-bbca-e491ea87a8b7 (api:48) 2021-09-22 10:39:36,605+0100 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '7.6', 'delay': '0.000470956', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=9e9cdb19-c502-4c26-bbca-e491ea87a8b7 (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,486::commands::98::common.commands::(run) SUCCESS: = b"oslo.privsep.daemon: Running privsep helper: ['sudo', 'privsep-helper', '--privsep_context', 'os_brick.privileged.default', '--privsep_sock_path', '/tmp/tmptcsu6fwy/privsep.sock']\noslo.privsep.daemon: Spawned new privsep daemon via rootwrap\noslo.privsep.daemon: privsep daemon starting\noslo.privsep.daemon: privsep process running with uid/gid: 0/0\noslo.privsep.daemon: privsep process running with capabilities (eff/prm/inh): CAP_SYS_ADMIN/CAP_SYS_ADMIN/none\noslo.privsep.daemon: privsep daemon running as pid 463597\nos_brick.initiator.connectors.iscsi: Trying to connect to iSCSI portal 10.187.21.238:3260\nos_brick.initiator.connectors.iscsi: Trying to connect to iSCSI portal 10.187.21.237:3260\n"; = 0 MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,487::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return managedvolume_run_helper with {'type': 'block', 'scsi_wwn': '360014054b727813d1bc4d4cefdade7db', 'path': '/dev/dm-42', 'multipath_id': '360014054b727813d1bc4d4cefdade7db'} ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:37,487+0100 INFO (jsonrpc/5) [storage.managevolumedb] Updating volume ed1a0e9f-4d30-4896-b965-534861cc0c02 path=/dev/mapper/360014054b727813d1bc4d4cefdade7db, attachment={'type': 'block', 'scsi_wwn': '360014054b727813d1bc4d4cefdade7db', 'path': '/dev/dm-42', 'multipath_id': '360014054b727813d1bc4d4cefdade7db'}, multipath_id=360014054b727813d1bc4d4cefdade7db (managedvolumedb:209) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,504::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call add_managed_udev_rule with ('ed1a0e9f-4d30-4896-b965-534861cc0c02', '/dev/mapper/360014054b727813d1bc4d4cefdade7db') {} MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,505::udev::124::SuperVdsm.ServerCallback::(add_managed_udev_rule) Creating rule /etc/udev/rules.d/99-vdsm-managed_ed1a0e9f-4d30-4896-b965-534861cc0c02.rules: 'SYMLINK=="mapper/360014054b727813d1bc4d4cefdade7db", RUN+="/usr/bin/chown vdsm:qemu $env{DEVNAME}"\n' MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,505::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return add_managed_udev_rule with None MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,505::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call trigger_managed_udev_rule with ('/dev/mapper/360014054b727813d1bc4d4cefdade7db',) {} MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,505::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /sbin/udevadm control --reload (cwd None) MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,519::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,520::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /sbin/udevadm trigger --verbose --action change --property-match=DEVLINKS=/dev/mapper/360014054b727813d1bc4d4cefdade7db (cwd None) ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:37,604+0100 INFO (jsonrpc/7) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:39:37,605+0100 INFO (jsonrpc/7) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192853452', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173652', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '106.14', 'cpuSys': '20.73', 'cpuUsage': '8049180000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514463653', 'tx': '83019177', 'sampleTime': 45369.805314218}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '0', 'writeLatency': '972399.3272727273', 'flushLatency': '354207.6538461539', 'writtenBytes': '2815353344', 'writeOps': '219085', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '0.0', 'writeRate': '34951.33230769245', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9185260', 'mem_free': '10224760', 'swap_in': 0, 'swap_out': 0, 'majflt': 0, 'minflt': 5686, 'pageflt': 5686}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '39', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,674::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|jsonrpc/5::DEBUG::2021-09-22 10:39:37,675::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return trigger_managed_udev_rule with None ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:37,675+0100 INFO (jsonrpc/5) [api.storage] FINISH attach_volume return={'result': {'attachment': {'type': 'block', 'scsi_wwn': '360014054b727813d1bc4d4cefdade7db', 'path': '/dev/dm-42', 'multipath_id': '360014054b727813d1bc4d4cefdade7db'}, 'path': '/dev/mapper/360014054b727813d1bc4d4cefdade7db', 'vol_id': 'ed1a0e9f-4d30-4896-b965-534861cc0c02'}, 'status': {'code': 0, 'message': 'Done'}} from=10.187.21.239,38252, flow_id=7e0493eb (api:54) 2021-09-22 10:39:37,675+0100 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call ManagedVolume.attach_volume took more than 1.00 seconds to succeed: 4.85 (__init__:316) 2021-09-22 10:39:37,696+0100 INFO (jsonrpc/1) [vdsm.api] START create_lease(lease={'sd_id': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'lease_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52'}, metadata={'generation': 0, 'job_status': 'PENDING', 'job_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'type': 'JOB'}) from=10.187.21.239,38276, flow_id=5dda520d, task_id=6a65e180-a543-472a-bcea-d7c0b26ca067 (api:48) 2021-09-22 10:39:37,706+0100 INFO (jsonrpc/1) [vdsm.api] FINISH create_lease return=None from=10.187.21.239,38276, flow_id=5dda520d, task_id=6a65e180-a543-472a-bcea-d7c0b26ca067 (api:54) 2021-09-22 10:39:37,719+0100 INFO (tasks/1) [storage.ThreadPool.WorkerThread] START task 6a65e180-a543-472a-bcea-d7c0b26ca067 (cmd=>, args=None) (threadPool:146) 2021-09-22 10:39:37,728+0100 INFO (tasks/1) [storage.xlease] Adding lease 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52' in lockspace 'a7ed0992-91f6-4236-8e18-29c5def2c845' (xlease:588) 2021-09-22 10:39:37,733+0100 INFO (tasks/1) [storage.SANLock] Acquiring Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) for host id 8, lvb=True (clusterlock:508) 2021-09-22 10:39:37,741+0100 INFO (tasks/1) [storage.SANLock] Successfully acquired Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) for host id 8 (clusterlock:568) 2021-09-22 10:39:37,742+0100 INFO (tasks/1) [storage.SANLock] Setting LVB data to lease Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728), info: {'type': 'JOB', 'generation': 0, 'job_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'job_status': 'PENDING', 'created': 1632303577, 'modified': 1632303577, 'host_hardware_id': '52c6eab1-08c6-085e-b773-5b4ed7268015'} (clusterlock:664) 2021-09-22 10:39:37,743+0100 INFO (tasks/1) [storage.SANLock] Releasing Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) (clusterlock:641) 2021-09-22 10:39:37,744+0100 INFO (tasks/1) [storage.SANLock] Successfully released Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) (clusterlock:661) 2021-09-22 10:39:37,753+0100 INFO (tasks/1) [storage.ThreadPool.WorkerThread] FINISH task 6a65e180-a543-472a-bcea-d7c0b26ca067 (threadPool:148) 2021-09-22 10:39:38,542+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33488 (protocoldetector:61) 2021-09-22 10:39:38,549+0100 WARN (Reactor thread) [vds.dispatcher] unhandled write event (betterAsyncore:184) 2021-09-22 10:39:38,550+0100 INFO (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from 127.0.0.1:33488 (protocoldetector:125) 2021-09-22 10:39:38,550+0100 INFO (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompserver:95) 2021-09-22 10:39:38,551+0100 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompserver:124) 2021-09-22 10:39:40,551+0100 WARN (JsonRpc (StompReactor)) [vds.dispatcher] unhandled close event (betterAsyncore:184) 2021-09-22 10:39:40,553+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33490 (protocoldetector:61) 2021-09-22 10:39:41,770+0100 INFO (jsonrpc/3) [vdsm.api] START getAllTasksStatuses() from=10.187.21.239,38252, task_id=11776af5-7ee0-4832-af87-59a1a2458957 (api:48) 2021-09-22 10:39:41,770+0100 INFO (jsonrpc/3) [vdsm.api] FINISH getAllTasksStatuses return={'allTasksStatus': {'2efd7c26-ec7c-4d84-8472-171b689386ab': {'taskID': '2efd7c26-ec7c-4d84-8472-171b689386ab', 'taskState': 'finished', 'taskResult': 'success', 'code': 0, 'message': '1 jobs completed successfully'}, '6a65e180-a543-472a-bcea-d7c0b26ca067': {'taskID': '6a65e180-a543-472a-bcea-d7c0b26ca067', 'taskState': 'finished', 'taskResult': 'success', 'code': 0, 'message': '1 jobs completed successfully'}}} from=10.187.21.239,38252, task_id=11776af5-7ee0-4832-af87-59a1a2458957 (api:54) 2021-09-22 10:39:41,788+0100 INFO (jsonrpc/0) [vdsm.api] START clearTask(taskID='6a65e180-a543-472a-bcea-d7c0b26ca067') from=10.187.21.239,38252, flow_id=5dda520d, task_id=87275139-bea8-4fd9-97e0-b87feaa553fd (api:48) 2021-09-22 10:39:41,791+0100 INFO (jsonrpc/0) [vdsm.api] FINISH clearTask return=None from=10.187.21.239,38252, flow_id=5dda520d, task_id=87275139-bea8-4fd9-97e0-b87feaa553fd (api:54) 2021-09-22 10:39:42,501+0100 INFO (periodic/0) [vdsm.api] START repoStats(domains=()) from=internal, task_id=75060f36-d8b7-4662-9a38-b0337076ff2d (api:48) 2021-09-22 10:39:42,502+0100 INFO (periodic/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '3.5', 'delay': '0.000496442', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '2.2', 'delay': '0.00218983', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.0', 'delay': '0.000437243', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=internal, task_id=75060f36-d8b7-4662-9a38-b0337076ff2d (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:42,519 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:42,545 - mom.RPCServer - INFO - getStatistics() 2021-09-22 10:39:43,430 - mom.RPCServer - INFO - ping() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:43,412+0100 INFO (jsonrpc/4) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:43,429+0100 INFO (jsonrpc/4) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=c0b3d191-16b1-4585-b5cc-4bec97652586 (api:48) 2021-09-22 10:39:43,429+0100 INFO (jsonrpc/4) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.4', 'delay': '0.000496442', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.2', 'delay': '0.00218983', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.9', 'delay': '0.000437243', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=c0b3d191-16b1-4585-b5cc-4bec97652586 (api:54) 2021-09-22 10:39:43,429+0100 INFO (jsonrpc/4) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=f4c6c195-5b08-4219-ae13-c54ca8b98824 (api:48) 2021-09-22 10:39:43,429+0100 INFO (jsonrpc/4) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=f4c6c195-5b08-4219-ae13-c54ca8b98824 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:43,431 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:43,438+0100 INFO (jsonrpc/4) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:43,447+0100 INFO (jsonrpc/5) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:43,465+0100 INFO (jsonrpc/5) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=b220f998-d5b1-4b35-9aca-d66791c7e97b (api:48) 2021-09-22 10:39:43,465+0100 INFO (jsonrpc/5) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.5', 'delay': '0.000496442', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.2', 'delay': '0.00218983', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '5.0', 'delay': '0.000437243', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=b220f998-d5b1-4b35-9aca-d66791c7e97b (api:54) 2021-09-22 10:39:43,465+0100 INFO (jsonrpc/5) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=f4ce8c51-0482-4e3f-814a-110e1a995314 (api:48) 2021-09-22 10:39:43,466+0100 INFO (jsonrpc/5) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=f4ce8c51-0482-4e3f-814a-110e1a995314 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:43,467 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:43,468 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:43,474+0100 INFO (jsonrpc/5) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:43,652+0100 INFO (monitor/e262737) [storage.StorageDomainCache] Removing domain e2627376-2254-4e90-9478-0223ef873214 from storage domain cache (sdc:211) 2021-09-22 10:39:43,653+0100 INFO (tmap-124/0) [IOProcessClient] (glusterSD/ovirt-macmini-35.lab.ced.bskyb.com:_BigScreenVolume) Starting client (__init__:340) 2021-09-22 10:39:43,662+0100 INFO (ioprocess/463786) [IOProcess] (glusterSD/ovirt-macmini-35.lab.ced.bskyb.com:_BigScreenVolume) Starting ioprocess (__init__:465) 2021-09-22 10:39:44,187+0100 INFO (jsonrpc/0) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=9bd94700-2362-428e-8497-dd10420e3905 (api:48) 2021-09-22 10:39:44,187+0100 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.2', 'delay': '0.000496442', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=9bd94700-2362-428e-8497-dd10420e3905 (api:54) 2021-09-22 10:39:45,112+0100 INFO (jsonrpc/6) [vdsm.api] START getSpmStatus(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38252, task_id=befed73a-01de-4e1a-a92b-cdbc07ea7675 (api:48) 2021-09-22 10:39:45,116+0100 INFO (jsonrpc/6) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmStatus': 'SPM', 'spmLver': 28, 'spmId': 8}} from=10.187.21.239,38252, task_id=befed73a-01de-4e1a-a92b-cdbc07ea7675 (api:54) 2021-09-22 10:39:45,159+0100 INFO (jsonrpc/2) [vdsm.api] START getStoragePoolInfo(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38276, task_id=df635755-5c0e-4161-abcb-c8c1a8723fd6 (api:48) 2021-09-22 10:39:45,163+0100 INFO (jsonrpc/2) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'domains': 'e2627376-2254-4e90-9478-0223ef873214:Active,176ed26c-5e20-4b2d-ab10-855f519e0b0f:Active,a7ed0992-91f6-4236-8e18-29c5def2c845:Active', 'isoprefix': '', 'lver': 28, 'master_uuid': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'master_ver': 1, 'name': 'No Description', 'pool_status': 'connected', 'spm_id': 8, 'type': 'ISCSI', 'version': '5'}, 'dominfo': {'e2627376-2254-4e90-9478-0223ef873214': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '778107871232', 'diskfree': '740668747776'}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '1610210082816', 'diskfree': '528817848320'}, 'a7ed0992-91f6-4236-8e18-29c5def2c845': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '106971529216', 'diskfree': '18119393280'}}} from=10.187.21.239,38276, task_id=df635755-5c0e-4161-abcb-c8c1a8723fd6 (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:45,570::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call dmsetup_run_status with ('multipath',) {} MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:45,570::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/dmsetup status --target multipath (cwd None) MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:45,584::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:45,584::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return dmsetup_run_status with b'360014054b727813d1bc4d4cefdade7db: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:112 A 0 0 1 E 0 1 2 8:128 A 0 0 1 \n36001405793765d9df7abd4849da87bdc: 0 4123000832 multipath 2 0 1 0 2 1 A 0 1 2 8:32 A 0 0 1 E 0 1 2 8:16 A 0 0 1 \n36001405534d4874d3b27d4d1cd86a0d0: 0 3145728000 multipath 2 0 1 0 2 1 A 0 1 2 8:96 A 0 0 1 E 0 1 2 8:80 A 0 0 1 \n36001405534d48dbda440d4f9bd8c15df: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:64 A 0 0 1 E 0 1 2 8:48 A 0 0 1 \n' ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:45,724+0100 INFO (monitor/e262737) [storage.StorageDomain] Removing remnants of deleted images [] (fileSD:735) 2021-09-22 10:39:46,620+0100 INFO (jsonrpc/7) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=2f91acb4-cff9-459f-a3e8-95c908ec479c (api:48) 2021-09-22 10:39:46,620+0100 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '7.6', 'delay': '0.000496442', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=2f91acb4-cff9-459f-a3e8-95c908ec479c (api:54) 2021-09-22 10:39:47,004+0100 INFO (jsonrpc/5) [vdsm.api] START lease_info(lease={'sd_id': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'lease_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52'}) from=10.187.21.239,38276, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a, task_id=fa4a229e-e82a-42bd-b45e-f925e88a4e4e (api:48) 2021-09-22 10:39:47,006+0100 INFO (jsonrpc/5) [vdsm.api] FINISH lease_info return={'result': {'sd_id': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'lease_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'path': '/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', 'offset': 3145728}} from=10.187.21.239,38276, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a, task_id=fa4a229e-e82a-42bd-b45e-f925e88a4e4e (api:54) 2021-09-22 10:39:47,734+0100 INFO (jsonrpc/3) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:39:47,735+0100 INFO (jsonrpc/3) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192863581', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173662', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '106.14', 'cpuSys': '20.73', 'cpuUsage': '8049180000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514463653', 'tx': '83019177', 'sampleTime': 45379.935289891}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '0', 'writeLatency': '972399.3272727273', 'flushLatency': '354207.6538461539', 'writtenBytes': '2815353344', 'writeOps': '219085', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '0.0', 'writeRate': '34951.33230769245', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9185260', 'mem_free': '10224760', 'swap_in': 0, 'swap_out': 0, 'majflt': 0, 'minflt': 5686, 'pageflt': 5686}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '39', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) 2021-09-22 10:39:49,021+0100 INFO (jsonrpc/0) [api.host] START getAllVmStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:39:49,023+0100 INFO (jsonrpc/0) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=10.187.21.239,38252 (api:54) 2021-09-22 10:39:49,068+0100 INFO (jsonrpc/6) [api.host] START getStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:39:49,091+0100 INFO (jsonrpc/6) [vdsm.api] START repoStats(domains=()) from=10.187.21.239,38252, task_id=605e7194-ac01-4cfa-8b5b-3dd2975c9031 (api:48) 2021-09-22 10:39:49,092+0100 INFO (jsonrpc/6) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '0.1', 'delay': '0.000470127', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.4', 'delay': '0.00218983', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '0.6', 'delay': '0.000451766', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=10.187.21.239,38252, task_id=605e7194-ac01-4cfa-8b5b-3dd2975c9031 (api:54) 2021-09-22 10:39:49,093+0100 INFO (jsonrpc/6) [vdsm.api] START multipath_health() from=10.187.21.239,38252, task_id=48d05e52-0017-4550-8290-ad123d913c76 (api:48) 2021-09-22 10:39:49,093+0100 INFO (jsonrpc/6) [vdsm.api] FINISH multipath_health return={} from=10.187.21.239,38252, task_id=48d05e52-0017-4550-8290-ad123d913c76 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:49,095 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:49,097 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:49,107+0100 INFO (jsonrpc/6) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=10.187.21.239,38252 (api:54) 2021-09-22 10:39:50,564+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33494 (protocoldetector:61) 2021-09-22 10:39:50,571+0100 WARN (Reactor thread) [vds.dispatcher] unhandled write event (betterAsyncore:184) 2021-09-22 10:39:50,571+0100 INFO (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from 127.0.0.1:33494 (protocoldetector:125) 2021-09-22 10:39:50,572+0100 INFO (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompserver:95) 2021-09-22 10:39:50,572+0100 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompserver:124) 2021-09-22 10:39:51,510+0100 INFO (jsonrpc/2) [api.host] START getAllVmStats() from=127.0.0.1,40080 (api:48) 2021-09-22 10:39:51,511+0100 INFO (jsonrpc/2) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=127.0.0.1,40080 (api:54) 2021-09-22 10:39:51,534+0100 INFO (jsonrpc/4) [api.host] START getAllVmIoTunePolicies() from=127.0.0.1,40080 (api:48) 2021-09-22 10:39:51,534+0100 INFO (jsonrpc/4) [api.host] FINISH getAllVmIoTunePolicies return={'status': {'code': 0, 'message': 'Done'}, 'io_tune_policies_dict': {'21a5b48e-218a-48ba-bf8e-60451f4d1793': {'policy': [], 'current_values': [{'name': 'vda', 'path': '/run/vdsm/storage/a7ed0992-91f6-4236-8e18-29c5def2c845/a3333af7-6967-4342-8f14-cf6f8924cd9d/f6f8d017-354f-466d-bc03-0b2d4a30dd63', 'ioTune': {'total_bytes_sec': 0, 'read_bytes_sec': 0, 'write_bytes_sec': 0, 'total_iops_sec': 0, 'write_iops_sec': 0, 'read_iops_sec': 0}}]}}} from=127.0.0.1,40080 (api:54) 2021-09-22 10:39:52,573+0100 WARN (JsonRpc (StompReactor)) [vds.dispatcher] unhandled close event (betterAsyncore:184) 2021-09-22 10:39:52,574+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33496 (protocoldetector:61) 2021-09-22 10:39:53,453+0100 INFO (jsonrpc/5) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:53,470+0100 INFO (jsonrpc/5) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=a92858cc-1f68-4f64-8e9b-ff304086d1ec (api:48) 2021-09-22 10:39:53,471+0100 INFO (jsonrpc/5) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.5', 'delay': '0.000470127', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.2', 'delay': '0.00455287', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '5.0', 'delay': '0.000451766', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=a92858cc-1f68-4f64-8e9b-ff304086d1ec (api:54) 2021-09-22 10:39:53,471+0100 INFO (jsonrpc/5) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=76a7cb08-cddf-4971-b286-272a78773928 (api:48) 2021-09-22 10:39:53,471+0100 INFO (jsonrpc/5) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=76a7cb08-cddf-4971-b286-272a78773928 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:53,473 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:53,474 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:53,481+0100 INFO (jsonrpc/5) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:53,488+0100 INFO (jsonrpc/3) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:39:53,505+0100 INFO (jsonrpc/3) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=7b9cfc94-2180-4a7f-8e1a-80c6980e1f5c (api:48) 2021-09-22 10:39:53,506+0100 INFO (jsonrpc/3) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.5', 'delay': '0.000470127', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.2', 'delay': '0.00455287', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '5.0', 'delay': '0.000451766', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=7b9cfc94-2180-4a7f-8e1a-80c6980e1f5c (api:54) 2021-09-22 10:39:53,506+0100 INFO (jsonrpc/3) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=68003e66-de88-425b-996f-e3621575ae07 (api:48) 2021-09-22 10:39:53,506+0100 INFO (jsonrpc/3) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=68003e66-de88-425b-996f-e3621575ae07 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:53,507 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:53,508 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:53,515+0100 INFO (jsonrpc/3) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:39:54,288+0100 INFO (jsonrpc/2) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=8fe2e2bd-4576-4a28-b0f0-af221e95321a (api:48) 2021-09-22 10:39:54,288+0100 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.3', 'delay': '0.000470127', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=8fe2e2bd-4576-4a28-b0f0-af221e95321a (api:54) 2021-09-22 10:39:55,176+0100 INFO (jsonrpc/4) [vdsm.api] START getSpmStatus(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38252, task_id=ea95a644-b3d5-4c61-a5b5-15fe3e92c0ad (api:48) 2021-09-22 10:39:55,179+0100 INFO (jsonrpc/4) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmStatus': 'SPM', 'spmLver': 28, 'spmId': 8}} from=10.187.21.239,38252, task_id=ea95a644-b3d5-4c61-a5b5-15fe3e92c0ad (api:54) 2021-09-22 10:39:55,184+0100 INFO (jsonrpc/7) [vdsm.api] START getStoragePoolInfo(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38276, task_id=52dd44db-594d-4f8e-a9e8-7e80f3e4995b (api:48) 2021-09-22 10:39:55,187+0100 INFO (jsonrpc/7) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'domains': 'e2627376-2254-4e90-9478-0223ef873214:Active,176ed26c-5e20-4b2d-ab10-855f519e0b0f:Active,a7ed0992-91f6-4236-8e18-29c5def2c845:Active', 'isoprefix': '', 'lver': 28, 'master_uuid': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'master_ver': 1, 'name': 'No Description', 'pool_status': 'connected', 'spm_id': 8, 'type': 'ISCSI', 'version': '5'}, 'dominfo': {'e2627376-2254-4e90-9478-0223ef873214': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '778107871232', 'diskfree': '740668747776'}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '1610210082816', 'diskfree': '528817848320'}, 'a7ed0992-91f6-4236-8e18-29c5def2c845': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '106971529216', 'diskfree': '18119393280'}}} from=10.187.21.239,38276, task_id=52dd44db-594d-4f8e-a9e8-7e80f3e4995b (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:55,585::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call dmsetup_run_status with ('multipath',) {} MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:55,585::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/dmsetup status --target multipath (cwd None) MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:55,597::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|mpathhealth::DEBUG::2021-09-22 10:39:55,597::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return dmsetup_run_status with b'360014054b727813d1bc4d4cefdade7db: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:112 A 0 0 1 E 0 1 2 8:128 A 0 0 1 \n36001405793765d9df7abd4849da87bdc: 0 4123000832 multipath 2 0 1 0 2 1 A 0 1 2 8:32 A 0 0 1 E 0 1 2 8:16 A 0 0 1 \n36001405534d4874d3b27d4d1cd86a0d0: 0 3145728000 multipath 2 0 1 0 2 1 A 0 1 2 8:96 A 0 0 1 E 0 1 2 8:80 A 0 0 1 \n36001405534d48dbda440d4f9bd8c15df: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:64 A 0 0 1 E 0 1 2 8:48 A 0 0 1 \n' ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:56,635+0100 INFO (jsonrpc/1) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=7bee30bb-ebd6-48f6-8606-23a66f904ac7 (api:48) 2021-09-22 10:39:56,635+0100 INFO (jsonrpc/1) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '7.6', 'delay': '0.000470127', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=7bee30bb-ebd6-48f6-8606-23a66f904ac7 (api:54) 2021-09-22 10:39:57,063+0100 INFO (jsonrpc/3) [vdsm.api] START sdm_copy_data(job_id='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', source={'endpoint_type': 'div', 'prepared': False, 'sd_id': 'e2627376-2254-4e90-9478-0223ef873214', 'img_id': '3c25d015-2bdc-4cff-987e-ff5caa04f028', 'vol_id': 'ccbb36f3-ed73-48d8-b152-2b48b2210fb1'}, destination={'generation': 0, 'is_zero': False, 'endpoint_type': 'external', 'format': 'raw', 'lease': {'sd_id': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'lease_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52'}, 'url': '/dev/mapper/360014054b727813d1bc4d4cefdade7db'}, copy_bitmaps=False) from=10.187.21.239,38252, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a, task_id=b91993af-6dec-4cd6-bf90-01c0b058d22b (api:48) 2021-09-22 10:39:57,064+0100 INFO (jsonrpc/3) [vdsm.api] FINISH sdm_copy_data return=None from=10.187.21.239,38252, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a, task_id=b91993af-6dec-4cd6-bf90-01c0b058d22b (api:54) 2021-09-22 10:39:57,064+0100 INFO (tasks/9) [storage.ThreadPool.WorkerThread] START task b91993af-6dec-4cd6-bf90-01c0b058d22b (cmd=>, args=None) (threadPool:146) 2021-09-22 10:39:57,064+0100 INFO (tasks/9) [root] Running job 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52'... (jobs:185) 2021-09-22 10:39:57,077+0100 INFO (jsonrpc/0) [api.host] START getJobs(job_type='storage', job_ids=['d2e9fc0d-95e2-48a5-bac3-67f62121cb52']) from=10.187.21.239,38252, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a (api:48) 2021-09-22 10:39:57,077+0100 INFO (jsonrpc/0) [api.host] FINISH getJobs return={'jobs': {'d2e9fc0d-95e2-48a5-bac3-67f62121cb52': {'id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'status': 'running', 'description': 'copy_data', 'job_type': 'storage'}}, 'status': {'code': 0, 'message': 'Done'}} from=10.187.21.239,38252, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a (api:54) 2021-09-22 10:39:57,092+0100 INFO (tasks/9) [storage.SANLock] Acquiring Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) for host id 8, lvb=True (clusterlock:508) 2021-09-22 10:39:57,100+0100 INFO (tasks/9) [storage.SANLock] Successfully acquired Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) for host id 8 (clusterlock:568) 2021-09-22 10:39:57,101+0100 INFO (tasks/9) [storage.VolumeManifest] Volume: preparing volume e2627376-2254-4e90-9478-0223ef873214/ccbb36f3-ed73-48d8-b152-2b48b2210fb1 (volume:604) 2021-09-22 10:39:57,132+0100 INFO (tasks/9) [storage.sdm.copy_data] Current lease a7ed0992-91f6-4236-8e18-29c5def2c845 metadata: {'type': 'JOB', 'generation': 0, 'job_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'job_status': 'PENDING', 'created': 1632303577, 'modified': 1632303577, 'host_hardware_id': '52c6eab1-08c6-085e-b773-5b4ed7268015'} (copy_data:301) 2021-09-22 10:39:57,169+0100 INFO (tasks/9) [storage.sdm.copy_data] Updated lease a7ed0992-91f6-4236-8e18-29c5def2c845 metadata: {'type': 'JOB', 'generation': 0, 'job_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'job_status': 'FAILED', 'created': 1632303577, 'modified': 1632303597, 'host_hardware_id': '52c6eab1-08c6-085e-b773-5b4ed7268015'} (copy_data:350) 2021-09-22 10:39:57,170+0100 INFO (tasks/9) [storage.SANLock] Setting LVB data to lease Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728), info: {'type': 'JOB', 'generation': 0, 'job_id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'job_status': 'FAILED', 'created': 1632303577, 'modified': 1632303597, 'host_hardware_id': '52c6eab1-08c6-085e-b773-5b4ed7268015'} (clusterlock:664) 2021-09-22 10:39:57,171+0100 INFO (tasks/9) [storage.SANLock] Releasing Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) (clusterlock:641) 2021-09-22 10:39:57,172+0100 INFO (tasks/9) [storage.SANLock] Successfully released Lease(name='d2e9fc0d-95e2-48a5-bac3-67f62121cb52', path='/dev/a7ed0992-91f6-4236-8e18-29c5def2c845/xleases', offset=3145728) (clusterlock:661) 2021-09-22 10:39:57,173+0100 ERROR (tasks/9) [root] Job 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52' failed (jobs:223) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/jobs.py", line 159, in run self._run() File "/usr/lib/python3.6/site-packages/vdsm/storage/sdm/api/copy_data.py", line 117, in _run self._operation.run() File "/usr/lib/python3.6/site-packages/vdsm/storage/qemuimg.py", line 354, in run for data in self._operation.watch(): File "/usr/lib/python3.6/site-packages/vdsm/storage/operation.py", line 106, in watch self._finalize(b"", err) File "/usr/lib/python3.6/site-packages/vdsm/storage/operation.py", line 179, in _finalize raise cmdutils.Error(self._cmd, rc, out, err) vdsm.common.cmdutils.Error: Command ['/usr/bin/qemu-img', 'convert', '-p', '-t', 'none', '-T', 'none', '-f', 'raw', '-O', 'raw', '-W', '/rhev/data-center/mnt/glusterSD/ovirt-macmini-35.lab.ced.bskyb.com:_BigScreenVolume/e2627376-2254-4e90-9478-0223ef873214/images/3c25d015-2bdc-4cff-987e-ff5caa04f028/ccbb36f3-ed73-48d8-b152-2b48b2210fb1', '/dev/mapper/360014054b727813d1bc4d4cefdade7db'] failed with rc=1 out=b'' err=bytearray(b"qemu-img: /dev/mapper/360014054b727813d1bc4d4cefdade7db: error while converting raw: Protocol driver \'host_device\' does not support image creation, and opening the image failed: Could not open \'/dev/mapper/360014054b727813d1bc4d4cefdade7db\': Permission denied\n") 2021-09-22 10:39:57,174+0100 INFO (tasks/9) [root] Job 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52' will be deleted in 3600 seconds (jobs:251) 2021-09-22 10:39:57,174+0100 INFO (tasks/9) [storage.ThreadPool.WorkerThread] FINISH task b91993af-6dec-4cd6-bf90-01c0b058d22b (threadPool:148) 2021-09-22 10:39:57,575+0100 INFO (periodic/3) [vdsm.api] START repoStats(domains=()) from=internal, task_id=3ab2f161-48ac-4dd0-b9fa-5d653e40427b (api:48) 2021-09-22 10:39:57,575+0100 INFO (periodic/3) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '8.6', 'delay': '0.000470127', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '1.8', 'delay': '0.00455287', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '4.1', 'delay': '0.000451766', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=internal, task_id=3ab2f161-48ac-4dd0-b9fa-5d653e40427b (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:39:57,592 - mom.RPCServer - INFO - ping() 2021-09-22 10:39:57,593 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:39:57,722+0100 INFO (jsonrpc/2) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:39:57,723+0100 INFO (jsonrpc/2) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192873570', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173672', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '46.19', 'cpuSys': '13.20', 'cpuUsage': '8051160000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514631288', 'tx': '83032078', 'sampleTime': 45389.923303757}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '0', 'writeLatency': '407703.0864197531', 'flushLatency': '217858.59210526315', 'writtenBytes': '2816231424', 'writeOps': '219166', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '0.0', 'writeRate': '58535.42808091808', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9286760', 'mem_free': '10326308', 'swap_in': 0, 'swap_out': 0, 'majflt': 0, 'minflt': 289, 'pageflt': 289}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '38', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) 2021-09-22 10:39:57,854+0100 INFO (jsonrpc/7) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:39:57,855+0100 INFO (jsonrpc/7) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192873702', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173673', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '46.19', 'cpuSys': '13.20', 'cpuUsage': '8051160000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514631288', 'tx': '83032078', 'sampleTime': 45390.05530337}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '0', 'writeLatency': '407703.0864197531', 'flushLatency': '217858.59210526315', 'writtenBytes': '2816231424', 'writeOps': '219166', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '0.0', 'writeRate': '58535.42808091808', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9286760', 'mem_free': '10326308', 'swap_in': 0, 'swap_out': 0, 'majflt': 0, 'minflt': 289, 'pageflt': 289}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '38', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) 2021-09-22 10:39:59,090+0100 INFO (jsonrpc/5) [api.host] START getJobs(job_type='storage', job_ids=['d2e9fc0d-95e2-48a5-bac3-67f62121cb52']) from=10.187.21.239,38252, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a (api:48) 2021-09-22 10:39:59,090+0100 INFO (jsonrpc/5) [api.host] FINISH getJobs return={'jobs': {'d2e9fc0d-95e2-48a5-bac3-67f62121cb52': {'id': 'd2e9fc0d-95e2-48a5-bac3-67f62121cb52', 'status': 'failed', 'description': 'copy_data', 'job_type': 'storage', 'progress': 0.0, 'error': {'code': 100, 'message': 'General Exception: (\'Command [\\\'/usr/bin/qemu-img\\\', \\\'convert\\\', \\\'-p\\\', \\\'-t\\\', \\\'none\\\', \\\'-T\\\', \\\'none\\\', \\\'-f\\\', \\\'raw\\\', \\\'-O\\\', \\\'raw\\\', \\\'-W\\\', \\\'/rhev/data-center/mnt/glusterSD/ovirt-macmini-35.lab.ced.bskyb.com:_BigScreenVolume/e2627376-2254-4e90-9478-0223ef873214/images/3c25d015-2bdc-4cff-987e-ff5caa04f028/ccbb36f3-ed73-48d8-b152-2b48b2210fb1\\\', \\\'/dev/mapper/360014054b727813d1bc4d4cefdade7db\\\'] failed with rc=1 out=b\\\'\\\' err=bytearray(b"qemu-img: /dev/mapper/360014054b727813d1bc4d4cefdade7db: error while converting raw: Protocol driver \\\\\\\'host_device\\\\\\\' does not support image creation, and opening the image failed: Could not open \\\\\\\'/dev/mapper/360014054b727813d1bc4d4cefdade7db\\\\\\\': Permission denied\\\\n")\',)'}}}, 'status': {'code': 0, 'message': 'Done'}} from=10.187.21.239,38252, flow_id=052f17fd-1fb2-4f4b-8eb3-237890ca597a (api:54) 2021-09-22 10:40:02,140+0100 INFO (jsonrpc/1) [api.storage] START detach_volume(vol_id='ed1a0e9f-4d30-4896-b965-534861cc0c02') from=10.187.21.239,38252, flow_id=2744a370 (api:48) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/1::DEBUG::2021-09-22 10:40:02,141::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call managedvolume_run_helper with ('detach',) {'cmd_input': {'vol_id': 'ed1a0e9f-4d30-4896-b965-534861cc0c02', 'connection_info': {'driver_volume_type': 'iscsi', 'data': {'target_discovered': False, 'target_iqn': 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'target_portal': '10.187.21.238:3260', 'volume_id': 'ed1a0e9f-4d30-4896-b965-534861cc0c02', 'access_mode': 'rw', 'discard': False, 'target_portals': ['10.187.21.238:3260', '10.187.21.237:3260'], 'target_iqns': ['iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02', 'iqn.2010-10.org.openstack:Cinder-Target-ed1a0e9f-4d30-4896-b965-534861cc0c02'], 'target_lun': 0, 'target_luns': [0, 0]}}, 'path': '/dev/mapper/360014054b727813d1bc4d4cefdade7db', 'attachment': {'type': 'block', 'scsi_wwn': '360014054b727813d1bc4d4cefdade7db', 'path': '/dev/dm-42', 'multipath_id': '360014054b727813d1bc4d4cefdade7db'}, 'multipath_id': '360014054b727813d1bc4d4cefdade7db'}} MainProcess|jsonrpc/1::DEBUG::2021-09-22 10:40:02,141::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/bin/python3 /usr/libexec/vdsm/managedvolume-helper detach (cwd None) ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:02,586+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33500 (protocoldetector:61) 2021-09-22 10:40:02,593+0100 WARN (Reactor thread) [vds.dispatcher] unhandled write event (betterAsyncore:184) 2021-09-22 10:40:02,593+0100 INFO (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from 127.0.0.1:33500 (protocoldetector:125) 2021-09-22 10:40:02,593+0100 INFO (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompserver:95) 2021-09-22 10:40:02,594+0100 INFO (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompserver:124) 2021-09-22 10:40:03,491+0100 INFO (jsonrpc/0) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:40:03,511+0100 INFO (jsonrpc/0) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=1393ce1a-a151-45a0-ba89-94fefd589d8a (api:48) 2021-09-22 10:40:03,512+0100 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.5', 'delay': '0.000463136', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.2', 'delay': '0.00214158', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '5.0', 'delay': '0.000470741', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=1393ce1a-a151-45a0-ba89-94fefd589d8a (api:54) 2021-09-22 10:40:03,512+0100 INFO (jsonrpc/0) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=98c2acf8-b13e-4c2a-9b54-b52793fc102f (api:48) 2021-09-22 10:40:03,512+0100 INFO (jsonrpc/0) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=98c2acf8-b13e-4c2a-9b54-b52793fc102f (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:40:03,515 - mom.RPCServer - INFO - ping() 2021-09-22 10:40:03,516 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:03,524+0100 INFO (jsonrpc/0) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:40:03,529+0100 INFO (jsonrpc/2) [api.host] START getStats() from=127.0.0.1,40072 (api:48) 2021-09-22 10:40:03,548+0100 INFO (jsonrpc/2) [vdsm.api] START repoStats(domains=()) from=127.0.0.1,40072, task_id=bbfe4b2a-97f0-4974-b9fa-5219c866357a (api:48) 2021-09-22 10:40:03,548+0100 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '4.5', 'delay': '0.000463136', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.3', 'delay': '0.00214158', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '0.0', 'delay': '0.000470741', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=bbfe4b2a-97f0-4974-b9fa-5219c866357a (api:54) 2021-09-22 10:40:03,549+0100 INFO (jsonrpc/2) [vdsm.api] START multipath_health() from=127.0.0.1,40072, task_id=b76e1ef9-c16d-4cf1-a536-7fd66adb1cb0 (api:48) 2021-09-22 10:40:03,549+0100 INFO (jsonrpc/2) [vdsm.api] FINISH multipath_health return={} from=127.0.0.1,40072, task_id=b76e1ef9-c16d-4cf1-a536-7fd66adb1cb0 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:40:03,550 - mom.RPCServer - INFO - ping() 2021-09-22 10:40:03,551 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:03,557+0100 INFO (jsonrpc/2) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=127.0.0.1,40072 (api:54) 2021-09-22 10:40:03,725+0100 INFO (periodic/3) [vdsm.api] START getVolumeSize(sdUUID='a7ed0992-91f6-4236-8e18-29c5def2c845', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='a3333af7-6967-4342-8f14-cf6f8924cd9d', volUUID='f6f8d017-354f-466d-bc03-0b2d4a30dd63') from=internal, task_id=fbb2b7db-f1e7-44e0-92aa-9299c6d0b39e (api:48) 2021-09-22 10:40:03,726+0100 INFO (periodic/3) [vdsm.api] FINISH getVolumeSize return={'apparentsize': '80530636800', 'truesize': '80530636800'} from=internal, task_id=fbb2b7db-f1e7-44e0-92aa-9299c6d0b39e (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|jsonrpc/1::DEBUG::2021-09-22 10:40:04,011::commands::98::common.commands::(run) SUCCESS: = b"oslo.privsep.daemon: Running privsep helper: ['sudo', 'privsep-helper', '--privsep_context', 'os_brick.privileged.default', '--privsep_sock_path', '/tmp/tmpcnxp1ebr/privsep.sock']\noslo.privsep.daemon: Spawned new privsep daemon via rootwrap\noslo.privsep.daemon: privsep daemon starting\noslo.privsep.daemon: privsep process running with uid/gid: 0/0\noslo.privsep.daemon: privsep process running with capabilities (eff/prm/inh): CAP_SYS_ADMIN/CAP_SYS_ADMIN/none\noslo.privsep.daemon: privsep daemon running as pid 463963\n"; = 0 MainProcess|jsonrpc/1::DEBUG::2021-09-22 10:40:04,011::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return managedvolume_run_helper with {} MainProcess|jsonrpc/1::DEBUG::2021-09-22 10:40:04,012::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call remove_managed_udev_rule with ('ed1a0e9f-4d30-4896-b965-534861cc0c02',) {} MainProcess|jsonrpc/1::DEBUG::2021-09-22 10:40:04,012::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return remove_managed_udev_rule with None ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:04,012+0100 INFO (jsonrpc/1) [storage.managevolumedb] Removing volume ed1a0e9f-4d30-4896-b965-534861cc0c02 (managedvolumedb:194) 2021-09-22 10:40:04,027+0100 INFO (jsonrpc/1) [api.storage] FINISH detach_volume return={'status': {'code': 0, 'message': 'Done'}} from=10.187.21.239,38252, flow_id=2744a370 (api:54) 2021-09-22 10:40:04,027+0100 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call ManagedVolume.detach_volume took more than 1.00 seconds to succeed: 1.89 (__init__:316) 2021-09-22 10:40:04,032+0100 INFO (jsonrpc/4) [api.host] START getAllVmStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:40:04,033+0100 INFO (jsonrpc/4) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=10.187.21.239,38252 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:40:04,108 - mom.RPCServer - INFO - ping() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:04,085+0100 INFO (jsonrpc/7) [api.host] START getStats() from=10.187.21.239,38252 (api:48) 2021-09-22 10:40:04,106+0100 INFO (jsonrpc/7) [vdsm.api] START repoStats(domains=()) from=10.187.21.239,38252, task_id=f1bbc5b4-d13c-4246-95e6-8eb1db19951a (api:48) 2021-09-22 10:40:04,106+0100 INFO (jsonrpc/7) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.1', 'delay': '0.000463136', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, 'e2627376-2254-4e90-9478-0223ef873214': {'code': 0, 'lastCheck': '3.8', 'delay': '0.00214158', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'code': 0, 'lastCheck': '0.6', 'delay': '0.000470741', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=10.187.21.239,38252, task_id=f1bbc5b4-d13c-4246-95e6-8eb1db19951a (api:54) 2021-09-22 10:40:04,106+0100 INFO (jsonrpc/7) [vdsm.api] START multipath_health() from=10.187.21.239,38252, task_id=ac14387a-8700-40f9-a329-2367c36a0f62 (api:48) 2021-09-22 10:40:04,107+0100 INFO (jsonrpc/7) [vdsm.api] FINISH multipath_health return={} from=10.187.21.239,38252, task_id=ac14387a-8700-40f9-a329-2367c36a0f62 (api:54) ==> /var/log/vdsm/mom.log <== 2021-09-22 10:40:04,109 - mom.RPCServer - INFO - getStatistics() ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:04,117+0100 INFO (jsonrpc/7) [api.host] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'info': (suppressed)} from=10.187.21.239,38252 (api:54) 2021-09-22 10:40:04,395+0100 INFO (jsonrpc/0) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=ec52ed8e-c3d6-4ed2-8edb-eb83a1b243d6 (api:48) 2021-09-22 10:40:04,395+0100 INFO (jsonrpc/0) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '5.4', 'delay': '0.000463136', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=ec52ed8e-c3d6-4ed2-8edb-eb83a1b243d6 (api:54) 2021-09-22 10:40:04,595+0100 WARN (JsonRpc (StompReactor)) [vds.dispatcher] unhandled close event (betterAsyncore:184) 2021-09-22 10:40:04,596+0100 INFO (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from 127.0.0.1:33502 (protocoldetector:61) 2021-09-22 10:40:05,206+0100 INFO (jsonrpc/6) [vdsm.api] START getSpmStatus(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38252, task_id=94f7771b-5cfb-438b-80be-656dcc0901ed (api:48) 2021-09-22 10:40:05,209+0100 INFO (jsonrpc/6) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmStatus': 'SPM', 'spmLver': 28, 'spmId': 8}} from=10.187.21.239,38252, task_id=94f7771b-5cfb-438b-80be-656dcc0901ed (api:54) 2021-09-22 10:40:05,256+0100 INFO (jsonrpc/2) [vdsm.api] START getStoragePoolInfo(spUUID='0eed07c4-782d-11eb-9ca3-00163e7a233b') from=10.187.21.239,38276, task_id=dcf6d869-828c-4ec5-90d7-d75e773477ff (api:48) 2021-09-22 10:40:05,260+0100 INFO (jsonrpc/2) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'domains': 'e2627376-2254-4e90-9478-0223ef873214:Active,176ed26c-5e20-4b2d-ab10-855f519e0b0f:Active,a7ed0992-91f6-4236-8e18-29c5def2c845:Active', 'isoprefix': '', 'lver': 28, 'master_uuid': 'a7ed0992-91f6-4236-8e18-29c5def2c845', 'master_ver': 1, 'name': 'No Description', 'pool_status': 'connected', 'spm_id': 8, 'type': 'ISCSI', 'version': '5'}, 'dominfo': {'e2627376-2254-4e90-9478-0223ef873214': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '778107871232', 'diskfree': '740668747776'}, '176ed26c-5e20-4b2d-ab10-855f519e0b0f': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '1610210082816', 'diskfree': '528817848320'}, 'a7ed0992-91f6-4236-8e18-29c5def2c845': {'status': 'Active', 'alerts': [], 'isoprefix': '', 'version': 5, 'disktotal': '106971529216', 'diskfree': '18119393280'}}} from=10.187.21.239,38276, task_id=dcf6d869-828c-4ec5-90d7-d75e773477ff (api:54) ==> /var/log/vdsm/supervdsm.log <== MainProcess|mpathhealth::DEBUG::2021-09-22 10:40:05,598::supervdsm_server::95::SuperVdsm.ServerCallback::(wrapper) call dmsetup_run_status with ('multipath',) {} MainProcess|mpathhealth::DEBUG::2021-09-22 10:40:05,598::commands::153::common.commands::(start) /usr/bin/taskset --cpu-list 0-23 /usr/sbin/dmsetup status --target multipath (cwd None) MainProcess|mpathhealth::DEBUG::2021-09-22 10:40:05,619::commands::98::common.commands::(run) SUCCESS: = b''; = 0 MainProcess|mpathhealth::DEBUG::2021-09-22 10:40:05,619::supervdsm_server::102::SuperVdsm.ServerCallback::(wrapper) return dmsetup_run_status with b'36001405793765d9df7abd4849da87bdc: 0 4123000832 multipath 2 0 1 0 2 1 A 0 1 2 8:32 A 0 0 1 E 0 1 2 8:16 A 0 0 1 \n36001405534d4874d3b27d4d1cd86a0d0: 0 3145728000 multipath 2 0 1 0 2 1 A 0 1 2 8:96 A 0 0 1 E 0 1 2 8:80 A 0 0 1 \n36001405534d48dbda440d4f9bd8c15df: 0 209715200 multipath 2 0 1 0 2 1 A 0 1 2 8:64 A 0 0 1 E 0 1 2 8:48 A 0 0 1 \n' ==> /var/log/vdsm/vdsm.log <== 2021-09-22 10:40:05,899+0100 INFO (health) [health] LVM cache hit ratio: 98.34% (hits: 29358 misses: 497) (health:131) 2021-09-22 10:40:06,530+0100 INFO (jsonrpc/1) [api.host] START getAllVmStats() from=127.0.0.1,40080 (api:48) 2021-09-22 10:40:06,532+0100 INFO (jsonrpc/1) [api.host] FINISH getAllVmStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': (suppressed)} from=127.0.0.1,40080 (api:54) 2021-09-22 10:40:06,549+0100 INFO (jsonrpc/4) [api.host] START getAllVmIoTunePolicies() from=127.0.0.1,40080 (api:48) 2021-09-22 10:40:06,550+0100 INFO (jsonrpc/4) [api.host] FINISH getAllVmIoTunePolicies return={'status': {'code': 0, 'message': 'Done'}, 'io_tune_policies_dict': {'21a5b48e-218a-48ba-bf8e-60451f4d1793': {'policy': [], 'current_values': [{'name': 'vda', 'path': '/run/vdsm/storage/a7ed0992-91f6-4236-8e18-29c5def2c845/a3333af7-6967-4342-8f14-cf6f8924cd9d/f6f8d017-354f-466d-bc03-0b2d4a30dd63', 'ioTune': {'total_bytes_sec': 0, 'read_bytes_sec': 0, 'write_bytes_sec': 0, 'total_iops_sec': 0, 'write_iops_sec': 0, 'read_iops_sec': 0}}]}}} from=127.0.0.1,40080 (api:54) 2021-09-22 10:40:06,642+0100 INFO (jsonrpc/5) [vdsm.api] START repoStats(domains=['a7ed0992-91f6-4236-8e18-29c5def2c845']) from=127.0.0.1,40072, task_id=907f6f84-1a2c-4996-9107-00208069c555 (api:48) 2021-09-22 10:40:06,642+0100 INFO (jsonrpc/5) [vdsm.api] FINISH repoStats return={'a7ed0992-91f6-4236-8e18-29c5def2c845': {'code': 0, 'lastCheck': '7.6', 'delay': '0.000463136', 'valid': True, 'version': 5, 'acquired': True, 'actual': True}} from=127.0.0.1,40072, task_id=907f6f84-1a2c-4996-9107-00208069c555 (api:54) 2021-09-22 10:40:07,967+0100 INFO (jsonrpc/0) [api.virt] START getStats() from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:48) 2021-09-22 10:40:07,968+0100 INFO (jsonrpc/0) [api.virt] FINISH getStats return={'status': {'code': 0, 'message': 'Done'}, 'statsList': [{'statusTime': '2192883814', 'status': 'Up', 'vmId': '21a5b48e-218a-48ba-bf8e-60451f4d1793', 'vmName': 'HostedEngine', 'vmType': 'kvm', 'kvmEnable': 'true', 'acpiEnable': 'true', 'elapsedTime': '173683', 'monitorResponse': '0', 'clientIp': '', 'timeOffset': '0', 'pauseCode': 'NOERR', 'cpuUser': '67.59', 'cpuSys': '19.47', 'cpuUsage': '8054080000000', 'network': {'vnet0': {'macAddr': '00:16:3e:7a:23:3b', 'name': 'vnet0', 'speed': '1000', 'state': 'unknown', 'rxErrors': '0', 'rxDropped': '0', 'txErrors': '0', 'txDropped': '0', 'rx': '514816694', 'tx': '83044059', 'sampleTime': 45400.167885013}}, 'disks': {'sdc': {'truesize': '0', 'apparentsize': '0', 'readLatency': '0', 'writeLatency': '0', 'flushLatency': '0', 'writtenBytes': '0', 'writeOps': '0', 'readOps': '0', 'readBytes': '0', 'readRate': '0.0', 'writeRate': '0.0'}, 'vda': {'truesize': '80530636800', 'apparentsize': '80530636800', 'readLatency': '0', 'writeLatency': '576321.8157894737', 'flushLatency': '218690.25373134328', 'writtenBytes': '2817046528', 'writeOps': '219242', 'readOps': '6455', 'readBytes': '110916608', 'readRate': '0.0', 'writeRate': '54339.302897546804', 'imageID': 'a3333af7-6967-4342-8f14-cf6f8924cd9d'}}, 'balloonInfo': {'balloon_max': '16777216', 'balloon_min': '1048576', 'balloon_cur': '16777216', 'balloon_target': '16777216', 'ballooning_enabled': True}, 'vcpuCount': '4', 'memoryStats': {'mem_total': '16199156', 'mem_unused': '9287064', 'mem_free': '10326648', 'swap_in': 0, 'swap_out': 0, 'majflt': 0, 'minflt': 45, 'pageflt': 45}, 'displayInfo': [{'type': 'spice', 'port': '5900', 'tlsPort': '5901', 'ipAddress': '10.187.21.14'}, {'type': 'vnc', 'port': '5902', 'tlsPort': '', 'ipAddress': '10.187.21.14'}], 'hash': '6634112141167993325', 'vmJobs': {}, 'vcpuQuota': '-1', 'vcpuPeriod': 100000, 'username': 'root', 'session': 'Unknown', 'memUsage': '38', 'guestCPUCount': -1, 'appsList': ('kernel-4.18.0-305.19.1.el8_4.x86_64', 'qemu-guest-agent-5.2.0'), 'guestIPs': '', 'guestFQDN': 'ovirtengine.devops.ced.bskyb.com', 'netIfaces': [{'hw': '00:00:00:00:00:00', 'inet': ['127.0.0.1'], 'inet6': ['::1'], 'name': 'lo'}, {'hw': '00:16:3e:7a:23:3b', 'inet': ['10.187.21.239'], 'inet6': ['fe80::216:3eff:fe7a:233b'], 'name': 'eth0'}], 'disksUsage': [{'path': '/', 'total': '7505707008', 'used': '4522221568', 'fs': 'xfs'}, {'path': '/tmp', 'total': '2136997888', 'used': '49258496', 'fs': 'xfs'}, {'path': '/boot', 'total': '1063256064', 'used': '421666816', 'fs': 'xfs'}, {'path': '/home', 'total': '1063256064', 'used': '41316352', 'fs': 'xfs'}, {'path': '/var', 'total': '21464350720', 'used': '1531756544', 'fs': 'xfs'}, {'path': '/var/log', 'total': '10726932480', 'used': '382787584', 'fs': 'xfs'}, {'path': '/var/log/audit', 'total': '1063256064', 'used': '46379008', 'fs': 'xfs'}], 'guestName': 'ovirtengine.devops.ced.bskyb.com', 'guestOs': '4.18.0-305.19.1.el8_4.x86_64', 'guestOsInfo': {'type': 'linux', 'arch': 'x86_64', 'kernel': '4.18.0-305.19.1.el8_4.x86_64', 'distribution': 'CentOS Linux', 'version': '8', 'codename': ''}, 'guestTimezone': {'offset': 60, 'zone': 'BST'}}]} from=127.0.0.1,40072, vmId=21a5b48e-218a-48ba-bf8e-60451f4d1793 (api:54) ^C [root@ovirt-macpro-14 ~]#