Attachment 640947 Details for Bug 874698 – vdsm59

vdsm59

vdsm59.log (text/plain), 57.21 KB, created by Pavel Stehlik on 2012-11-08 17:00:21 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Pavel Stehlik

Created: 2012-11-08 17:00:21 UTC

Size: 57.21 KB

patch

obsolete

>Thread-9851::DEBUG::2012-11-08 16:51:57,499::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15fa1e50>]
>Thread-9851::DEBUG::2012-11-08 16:51:57,499::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 809d0498-1cc4-4d7e-bb60-bb3cfbb937c5 releasing
>Thread-9851::DEBUG::2012-11-08 16:51:57,499::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9851::DEBUG::2012-11-08 16:51:57,500::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9851::DEBUG::2012-11-08 16:51:57,500::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9851::DEBUG::2012-11-08 16:51:57,500::resource::503::irs::Owner 809d0498-1cc4-4d7e-bb60-bb3cfbb937c5: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15fa1e50> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15fa1e50>'])
>Thread-9851::DEBUG::2012-11-08 16:51:57,500::task::577::irs::Task 809d0498-1cc4-4d7e-bb60-bb3cfbb937c5: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9851::DEBUG::2012-11-08 16:51:57,500::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9851::DEBUG::2012-11-08 16:51:57,500::task::577::irs::Task 809d0498-1cc4-4d7e-bb60-bb3cfbb937c5: ref 0 aborting False
>Thread-9851::INFO::2012-11-08 16:51:57,501::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00401878356934', 'lastCheck': 1352393513.2147689, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00410914421082', 'lastCheck': 1352393513.254837, 'valid': True, 'code': 0}}
>Thread-9858::INFO::2012-11-08 16:52:07,600::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9858::DEBUG::2012-11-08 16:52:07,600::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: moving from state init -> state preparing
>Thread-9858::DEBUG::2012-11-08 16:52:07,600::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: b1242063-ff99-4007-ad9d-34d24f971ae4 acquire shared (120000)
>Thread-9858::DEBUG::2012-11-08 16:52:07,601::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9858::DEBUG::2012-11-08 16:52:07,601::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to 'b1242063-ff99-4007-ad9d-34d24f971ae4'
>Thread-9858::DEBUG::2012-11-08 16:52:07,601::resource::524::irs::Owner b1242063-ff99-4007-ad9d-34d24f971ae4: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9858::DEBUG::2012-11-08 16:52:07,601::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9858::DEBUG::2012-11-08 16:52:07,601::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: ref 1 aborting False
>Thread-9858::DEBUG::2012-11-08 16:52:07,601::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00448298454285', 'lastCheck': 1352393523.2195749, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00405406951904', 'lastCheck': 1352393523.260154, 'valid': True, 'code': 0}}
>Thread-9858::DEBUG::2012-11-08 16:52:07,602::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: moving from state preparing -> state finished
>Thread-9858::DEBUG::2012-11-08 16:52:07,602::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15fa18d0>]
>Thread-9858::DEBUG::2012-11-08 16:52:07,602::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: b1242063-ff99-4007-ad9d-34d24f971ae4 releasing
>Thread-9858::DEBUG::2012-11-08 16:52:07,602::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9858::DEBUG::2012-11-08 16:52:07,602::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9858::DEBUG::2012-11-08 16:52:07,603::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9858::DEBUG::2012-11-08 16:52:07,603::resource::503::irs::Owner b1242063-ff99-4007-ad9d-34d24f971ae4: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15fa18d0> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15fa18d0>'])
>Thread-9858::DEBUG::2012-11-08 16:52:07,603::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9858::DEBUG::2012-11-08 16:52:07,603::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9858::DEBUG::2012-11-08 16:52:07,603::task::577::irs::Task b1242063-ff99-4007-ad9d-34d24f971ae4: ref 0 aborting False
>Thread-9858::INFO::2012-11-08 16:52:07,603::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00448298454285', 'lastCheck': 1352393523.2195749, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00405406951904', 'lastCheck': 1352393523.260154, 'valid': True, 'code': 0}}
>Thread-9860::DEBUG::2012-11-08 16:52:08,732::vm::1296::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::shutdown Called
>Thread-9860::DEBUG::2012-11-08 16:52:08,732::vm::1315::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::acpi shutdown called
>QMon-9776::DEBUG::2012-11-08 16:52:08,763::vm::965::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::onShutdown() event
>QMon-9776::DEBUG::2012-11-08 16:52:08,764::QemuMonitor::317::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::# GUEST: Got powerdown request
>Thread-9863::DEBUG::2012-11-08 16:52:10,628::vm::1198::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::spice.set_ticket DonZ54Q5tmL9 expiration=120,connected=disconnect
>Thread-9777::DEBUG::2012-11-08 16:52:13,090::guestIF::261::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::Guest connection timed out
>QMon-9776::DEBUG::2012-11-08 16:52:13,619::QemuMonitor::317::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::# spice: version mismatch client 2.2 server 1.1
>Thread-5005::DEBUG::2012-11-08 16:52:14,667::guestIF::261::vds.vmlog.ceda1c63-d522-4add-bd81-8f0647a8fe9e::Guest connection timed out
>Thread-9870::INFO::2012-11-08 16:52:17,764::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9870::DEBUG::2012-11-08 16:52:17,764::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: moving from state init -> state preparing
>Thread-9870::DEBUG::2012-11-08 16:52:17,765::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 0ddb33a1-a360-467c-9adf-37aba1a93365 acquire shared (120000)
>Thread-9870::DEBUG::2012-11-08 16:52:17,765::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9870::DEBUG::2012-11-08 16:52:17,765::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '0ddb33a1-a360-467c-9adf-37aba1a93365'
>Thread-9870::DEBUG::2012-11-08 16:52:17,765::resource::524::irs::Owner 0ddb33a1-a360-467c-9adf-37aba1a93365: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9870::DEBUG::2012-11-08 16:52:17,766::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9870::DEBUG::2012-11-08 16:52:17,766::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: ref 1 aborting False
>Thread-9870::DEBUG::2012-11-08 16:52:17,766::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00396800041199', 'lastCheck': 1352393533.223433, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00412201881409', 'lastCheck': 1352393533.2645941, 'valid': True, 'code': 0}}
>Thread-9870::DEBUG::2012-11-08 16:52:17,766::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: moving from state preparing -> state finished
>Thread-9870::DEBUG::2012-11-08 16:52:17,766::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9a310>]
>Thread-9870::DEBUG::2012-11-08 16:52:17,767::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 0ddb33a1-a360-467c-9adf-37aba1a93365 releasing
>Thread-9870::DEBUG::2012-11-08 16:52:17,767::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9870::DEBUG::2012-11-08 16:52:17,767::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9870::DEBUG::2012-11-08 16:52:17,767::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9870::DEBUG::2012-11-08 16:52:17,767::resource::503::irs::Owner 0ddb33a1-a360-467c-9adf-37aba1a93365: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9a310> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9a310>'])
>Thread-9870::DEBUG::2012-11-08 16:52:17,767::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9870::DEBUG::2012-11-08 16:52:17,768::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9870::DEBUG::2012-11-08 16:52:17,768::task::577::irs::Task 0ddb33a1-a360-467c-9adf-37aba1a93365: ref 0 aborting False
>Thread-9870::INFO::2012-11-08 16:52:17,768::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00396800041199', 'lastCheck': 1352393533.223433, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00412201881409', 'lastCheck': 1352393533.2645941, 'valid': True, 'code': 0}}
>Thread-9880::INFO::2012-11-08 16:52:27,924::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9880::DEBUG::2012-11-08 16:52:27,924::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: moving from state init -> state preparing
>Thread-9880::DEBUG::2012-11-08 16:52:27,924::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 2173ebb5-12b4-4dc9-8081-8621024e273e acquire shared (120000)
>Thread-9880::DEBUG::2012-11-08 16:52:27,924::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9880::DEBUG::2012-11-08 16:52:27,925::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '2173ebb5-12b4-4dc9-8081-8621024e273e'
>Thread-9880::DEBUG::2012-11-08 16:52:27,925::resource::524::irs::Owner 2173ebb5-12b4-4dc9-8081-8621024e273e: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9880::DEBUG::2012-11-08 16:52:27,925::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9880::DEBUG::2012-11-08 16:52:27,925::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: ref 1 aborting False
>Thread-9880::DEBUG::2012-11-08 16:52:27,925::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00403881072998', 'lastCheck': 1352393543.2278719, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00401401519775', 'lastCheck': 1352393543.2688551, 'valid': True, 'code': 0}}
>Thread-9880::DEBUG::2012-11-08 16:52:27,926::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: moving from state preparing -> state finished
>Thread-9880::DEBUG::2012-11-08 16:52:27,926::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15fa1c50>]
>Thread-9880::DEBUG::2012-11-08 16:52:27,926::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 2173ebb5-12b4-4dc9-8081-8621024e273e releasing
>Thread-9880::DEBUG::2012-11-08 16:52:27,926::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9880::DEBUG::2012-11-08 16:52:27,926::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9880::DEBUG::2012-11-08 16:52:27,927::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9880::DEBUG::2012-11-08 16:52:27,927::resource::503::irs::Owner 2173ebb5-12b4-4dc9-8081-8621024e273e: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15fa1c50> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15fa1c50>'])
>Thread-9880::DEBUG::2012-11-08 16:52:27,927::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9880::DEBUG::2012-11-08 16:52:27,927::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9880::DEBUG::2012-11-08 16:52:27,927::task::577::irs::Task 2173ebb5-12b4-4dc9-8081-8621024e273e: ref 0 aborting False
>Thread-9880::INFO::2012-11-08 16:52:27,928::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00403881072998', 'lastCheck': 1352393543.2278719, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00401401519775', 'lastCheck': 1352393543.2688551, 'valid': True, 'code': 0}}
>QMon-9776::ERROR::2012-11-08 16:52:31,636::QemuMonitor::268::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::QemuMonitor
>Traceback (most recent call last):
>  File "/usr/share/vdsm/QemuMonitor.py", line 266, in _work
>  File "/usr/share/vdsm/QemuMonitor.py", line 192, in _work
>  File "<string>", line 1, in sendall
>error: (32, 'Broken pipe')
>QMon-9776::DEBUG::2012-11-08 16:52:31,637::vm::965::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::onShutdown() event
>QMon-9776::DEBUG::2012-11-08 16:52:31,637::QemuMonitor::317::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::# GUEST: Got shutdown request
>QMon-9776::INFO::2012-11-08 16:52:31,637::vm::720::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::Monitor stopped
>QMon-9776::DEBUG::2012-11-08 16:52:31,637::vm::1464::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::Changed state to Down: User shut down
>Thread-9778::ERROR::2012-11-08 16:52:31,638::utils::427::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::Traceback (most recent call last):
>  File "/usr/share/vdsm/utils.py", line 421, in run
>  File "/usr/share/vdsm/vm.py", line 136, in sample
>  File "/usr/share/vdsm/vm.py", line 73, in __init__
>  File "/usr/share/vdsm/vm.py", line 51, in __init__
>  File "/usr/share/vdsm/vm.py", line 1201, in _sendMonitorCommand
>  File "/usr/share/vdsm/QemuMonitor.py", line 130, in sendCommand
>  File "/usr/share/vdsm/QemuMonitor.py", line 51, in wait
>error: (32, 'Broken pipe')
>
>Thread-9888::DEBUG::2012-11-08 16:52:32,034::vm::1339::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::destroy Called
>Thread-9888::DEBUG::2012-11-08 16:52:35,036::vm::1391::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::Total desktops after destroy of 8412e921-4fd3-4b82-a1a3-eaece70deae2 is 1
>Thread-9888::DEBUG::2012-11-08 16:52:35,036::vm::1395::vds.vmlog.8412e921-4fd3-4b82-a1a3-eaece70deae2::qemu stdouterr: QEMU waiting for connection on: unix:/var/vdsm/8412e921-4fd3-4b82-a1a3-eaece70deae2.monitor.socket,server
>QEMU waiting for connection on: unix:/var/vdsm/8412e921-4fd3-4b82-a1a3-eaece70deae2.guest.socket,server
>interface_change_notifier: VD_INTERFACE_MIGRATION
>migration_notify_register: record=0x1d26ef0 opaque=(nil) key=spice_mig_ext mstarted=0x2ad959390b30 mfinished=0x2ad959392520 mig_recv=0x2ad95938e3e0
>interface_change_notifier: VD_INTERFACE_QTERM
>init_qxl_ram: npages 14357
>qxl_init: rom(0x2ad9a57f2000, 0x45040000, 0x2000) ram(0x2ad9a17f2000, 0x41040000, 0x4000000) vram(0x2ad9a57f4000, 0x45042000, 0x1000)
>interface_change_notifier: VD_INTERFACE_QXL
>red_worker_main: begin
>0: qxl_enter_vga_mode
>handle_dev_input: attach
>create_cairo_context: using cairo canvas
>interface_change_notifier: VD_INTERFACE_KEYBOARD
>interface_change_notifier: VD_INTERFACE_MOUSE
>interface_audio_init: 
>interface_change_notifier: VD_INTERFACE_PLAYBACK
>interface_change_notifier: VD_INTERFACE_RECORD
>line_in_init: 
>line_out_init: freq 44100 channels 2 format AUD_FMT_S16 HOST_ENDIANNESS
>QXL: qxl_vm_change_state_handler: running=1
>handle_dev_input: start
>qxl_display_resize
>qxl_reset
>handle_dev_input: detach
>handle_dev_input: attach
>create_cairo_context: using cairo canvas
>vdi_port_io_map: base 0xc140 size 0x10
>vdi_port_ram_map: addr 0xc1000000 size 0x10000
>ram_map: addr 0xc4000000 size 0x4000000
>vram_map: addr 0xc8000000 size 0x1000
>rom_map: addr 0xc8002000 size 0x2000
>ioport_map: base 0xc150 size 0x8
>qxl_display_resize
>qxl_reset
>handle_dev_input: detach
>handle_dev_input: attach
>create_cairo_context: using cairo canvas
>reds_handle_read_header_done: version mismatch
>vdi_port_io_map: base 0xc140 size 0x10
>vdi_port_ram_map: addr 0xc1000000 size 0x10000
>ram_map: addr 0xc4000000 size 0x4000000
>vram_map: addr 0xc8000000 size 0x1000
>rom_map: addr 0xc8002000 size 0x2000
>ioport_map: base 0xc150 size 0x8
>ram_map: addr 0xc4000000 size 0x4000000
>vram_map: addr 0xc8000000 size 0x1000
>rom_map: addr 0xc8002000 size 0x2000
>ioport_map: base 0xc150 size 0x8
>interface_change_notifier: VD_INTERFACE_TABLET
>qxl_display_resize
>qxl_reset
>handle_dev_input: detach
>handle_dev_input: attach
>create_cairo_context: using cairo canvas
>reds_handle_read_header_done: version mismatch
>/etc/qemu-ifdown: could not launch network script
>interface_audio_fini: 
>interface_change_notifier: remove VD_INTERFACE_PLAYBACK
>interface_change_notifier: remove VD_INTERFACE_RECORD
>
>Thread-9888::INFO::2012-11-08 16:52:35,038::dispatcher::95::irs::Run and protect: teardownVolume, args: ( sdUUID=756f1734-2600-456f-a4b1-4b6256a83316 spUUID=34eb6fe7-fee0-451a-8528-1829edf060de imgUUID=1d95b0d3-964c-4d62-a4de-a2e3845676f5 volUUID=63d277f6-8991-4d4a-bd7e-09912d3cd6dc rw=False)
>Thread-9888::DEBUG::2012-11-08 16:52:35,038::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: moving from state init -> state preparing
>Thread-9888::INFO::2012-11-08 16:52:35,038::sp::1385::irs::(StoragePool.getDomains) Get storage pool domains: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': 'Active', '756f1734-2600-456f-a4b1-4b6256a83316': 'Active'}
>Thread-9888::INFO::2012-11-08 16:52:35,038::fileSD::214::irs::(FileStorageDomain.validate) sdUUID=756f1734-2600-456f-a4b1-4b6256a83316
>Thread-9888::DEBUG::2012-11-08 16:52:35,039::misc::100::irs::'/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv1_pstehlik_nfs02/756f1734-2600-456f-a4b1-4b6256a83316/dom_md/metadata' (cwd None)
>Thread-9888::DEBUG::2012-11-08 16:52:35,058::misc::123::irs::SUCCESS: <err> = '1+1 records in\n1+1 records out\n532 bytes (532 B) copied, 0.0009 seconds, 591 kB/s\n'; <rc> = 0
>Thread-9888::DEBUG::2012-11-08 16:52:35,058::metadata::89::irs::metadata.__validate() __cksum(md) = edfd6699dc1a1ddc9b3037ed9b484606660eccb4
>Thread-9888::DEBUG::2012-11-08 16:52:35,058::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: edcf3722-7277-492d-b9f8-6d36542e3bd7 acquire shared (120000)
>Thread-9888::DEBUG::2012-11-08 16:52:35,058::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9888::DEBUG::2012-11-08 16:52:35,059::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to 'edcf3722-7277-492d-b9f8-6d36542e3bd7'
>Thread-9888::DEBUG::2012-11-08 16:52:35,059::resource::524::irs::Owner edcf3722-7277-492d-b9f8-6d36542e3bd7: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9888::DEBUG::2012-11-08 16:52:35,059::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9888::DEBUG::2012-11-08 16:52:35,059::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: ref 1 aborting False
>Thread-9888::DEBUG::2012-11-08 16:52:35,059::fileVolume::447::irs::validate image 1d95b0d3-964c-4d62-a4de-a2e3845676f5 path for 63d277f6-8991-4d4a-bd7e-09912d3cd6dc
>Thread-9888::DEBUG::2012-11-08 16:52:35,060::fileVolume::483::irs::validate path for 63d277f6-8991-4d4a-bd7e-09912d3cd6dc
>Thread-9888::INFO::2012-11-08 16:52:35,063::volume::517::irs::Volume: tearing down volume 756f1734-2600-456f-a4b1-4b6256a83316/63d277f6-8991-4d4a-bd7e-09912d3cd6dc justme False
>Thread-9888::DEBUG::2012-11-08 16:52:35,065::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: finished: None
>Thread-9888::DEBUG::2012-11-08 16:52:35,065::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: moving from state preparing -> state finished
>Thread-9888::DEBUG::2012-11-08 16:52:35,065::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f84210>]
>Thread-9888::DEBUG::2012-11-08 16:52:35,065::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: edcf3722-7277-492d-b9f8-6d36542e3bd7 releasing
>Thread-9888::DEBUG::2012-11-08 16:52:35,066::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9888::DEBUG::2012-11-08 16:52:35,066::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9888::DEBUG::2012-11-08 16:52:35,066::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9888::DEBUG::2012-11-08 16:52:35,066::resource::503::irs::Owner edcf3722-7277-492d-b9f8-6d36542e3bd7: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f84210> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f84210>'])
>Thread-9888::DEBUG::2012-11-08 16:52:35,066::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9888::DEBUG::2012-11-08 16:52:35,066::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9888::DEBUG::2012-11-08 16:52:35,067::task::577::irs::Task edcf3722-7277-492d-b9f8-6d36542e3bd7: ref 0 aborting False
>Thread-9888::INFO::2012-11-08 16:52:35,067::dispatcher::101::irs::Run and protect: teardownVolume, Return response: {'status': {'message': 'OK', 'code': 0}}
>Thread-5006::INFO::2012-11-08 16:52:40,943::dispatcher::95::irs::Run and protect: getVolumeSize, args: ( sdUUID=756f1734-2600-456f-a4b1-4b6256a83316 spUUID=34eb6fe7-fee0-451a-8528-1829edf060de imgUUID=bcf6d4d2-d52b-493b-ab28-915e26c3b03d volUUID=88df524e-8276-407a-8426-80b7d54be180)
>Thread-5006::DEBUG::2012-11-08 16:52:40,944::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: moving from state init -> state preparing
>Thread-5006::INFO::2012-11-08 16:52:40,944::sp::1385::irs::(StoragePool.getDomains) Get storage pool domains: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': 'Active', '756f1734-2600-456f-a4b1-4b6256a83316': 'Active'}
>Thread-5006::INFO::2012-11-08 16:52:40,944::fileSD::214::irs::(FileStorageDomain.validate) sdUUID=756f1734-2600-456f-a4b1-4b6256a83316
>Thread-5006::DEBUG::2012-11-08 16:52:40,944::misc::100::irs::'/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv1_pstehlik_nfs02/756f1734-2600-456f-a4b1-4b6256a83316/dom_md/metadata' (cwd None)
>Thread-5006::DEBUG::2012-11-08 16:52:40,964::misc::123::irs::SUCCESS: <err> = '1+1 records in\n1+1 records out\n532 bytes (532 B) copied, 0.000832 seconds, 639 kB/s\n'; <rc> = 0
>Thread-5006::DEBUG::2012-11-08 16:52:40,964::metadata::89::irs::metadata.__validate() __cksum(md) = edfd6699dc1a1ddc9b3037ed9b484606660eccb4
>Thread-5006::DEBUG::2012-11-08 16:52:40,965::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: cd38e67b-723d-405c-b2d7-9a386c832b61 acquire shared (120000)
>Thread-5006::DEBUG::2012-11-08 16:52:40,965::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-5006::DEBUG::2012-11-08 16:52:40,965::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to 'cd38e67b-723d-405c-b2d7-9a386c832b61'
>Thread-5006::DEBUG::2012-11-08 16:52:40,965::resource::524::irs::Owner cd38e67b-723d-405c-b2d7-9a386c832b61: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-5006::DEBUG::2012-11-08 16:52:40,965::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-5006::DEBUG::2012-11-08 16:52:40,966::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: ref 1 aborting False
>Thread-5006::DEBUG::2012-11-08 16:52:40,966::fileVolume::447::irs::validate image bcf6d4d2-d52b-493b-ab28-915e26c3b03d path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:52:40,968::fileVolume::483::irs::validate path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:52:40,970::fileVolume::447::irs::validate image bcf6d4d2-d52b-493b-ab28-915e26c3b03d path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:52:40,971::fileVolume::483::irs::validate path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:52:40,973::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: finished: {'truesize': '2962411520', 'apparentsize': '7516192768'}
>Thread-5006::DEBUG::2012-11-08 16:52:40,973::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: moving from state preparing -> state finished
>Thread-5006::DEBUG::2012-11-08 16:52:40,973::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f84c50>]
>Thread-5006::DEBUG::2012-11-08 16:52:40,973::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: cd38e67b-723d-405c-b2d7-9a386c832b61 releasing
>Thread-5006::DEBUG::2012-11-08 16:52:40,973::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-5006::DEBUG::2012-11-08 16:52:40,974::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-5006::DEBUG::2012-11-08 16:52:40,974::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-5006::DEBUG::2012-11-08 16:52:40,974::resource::503::irs::Owner cd38e67b-723d-405c-b2d7-9a386c832b61: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f84c50> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f84c50>'])
>Thread-5006::DEBUG::2012-11-08 16:52:40,974::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-5006::DEBUG::2012-11-08 16:52:40,974::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-5006::DEBUG::2012-11-08 16:52:40,974::task::577::irs::Task cd38e67b-723d-405c-b2d7-9a386c832b61: ref 0 aborting False
>Thread-5006::INFO::2012-11-08 16:52:40,975::dispatcher::101::irs::Run and protect: getVolumeSize, Return response: {'status': {'message': 'OK', 'code': 0}, 'truesize': '2962411520', 'apparentsize': '7516192768'}
>Thread-9892::INFO::2012-11-08 16:52:41,142::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9892::DEBUG::2012-11-08 16:52:41,142::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: moving from state init -> state preparing
>Thread-9892::DEBUG::2012-11-08 16:52:41,142::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 2d93bebb-460a-4f49-a3ec-e055ba9672a8 acquire shared (120000)
>Thread-9892::DEBUG::2012-11-08 16:52:41,142::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9892::DEBUG::2012-11-08 16:52:41,143::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '2d93bebb-460a-4f49-a3ec-e055ba9672a8'
>Thread-9892::DEBUG::2012-11-08 16:52:41,143::resource::524::irs::Owner 2d93bebb-460a-4f49-a3ec-e055ba9672a8: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9892::DEBUG::2012-11-08 16:52:41,143::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9892::DEBUG::2012-11-08 16:52:41,143::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: ref 1 aborting False
>Thread-9892::DEBUG::2012-11-08 16:52:41,143::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.0039119720459', 'lastCheck': 1352393553.2311139, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00403308868408', 'lastCheck': 1352393553.2722471, 'valid': True, 'code': 0}}
>Thread-9892::DEBUG::2012-11-08 16:52:41,144::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: moving from state preparing -> state finished
>Thread-9892::DEBUG::2012-11-08 16:52:41,144::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9ab90>]
>Thread-9892::DEBUG::2012-11-08 16:52:41,144::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 2d93bebb-460a-4f49-a3ec-e055ba9672a8 releasing
>Thread-9892::DEBUG::2012-11-08 16:52:41,144::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9892::DEBUG::2012-11-08 16:52:41,144::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9892::DEBUG::2012-11-08 16:52:41,145::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9892::DEBUG::2012-11-08 16:52:41,145::resource::503::irs::Owner 2d93bebb-460a-4f49-a3ec-e055ba9672a8: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9ab90> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9ab90>'])
>Thread-9892::DEBUG::2012-11-08 16:52:41,145::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9892::DEBUG::2012-11-08 16:52:41,145::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9892::DEBUG::2012-11-08 16:52:41,145::task::577::irs::Task 2d93bebb-460a-4f49-a3ec-e055ba9672a8: ref 0 aborting False
>Thread-9892::INFO::2012-11-08 16:52:41,145::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.0039119720459', 'lastCheck': 1352393553.2311139, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00403308868408', 'lastCheck': 1352393553.2722471, 'valid': True, 'code': 0}}
>Thread-5005::DEBUG::2012-11-08 16:52:44,667::guestIF::261::vds.vmlog.ceda1c63-d522-4add-bd81-8f0647a8fe9e::Guest connection timed out
>Thread-9898::INFO::2012-11-08 16:52:51,352::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9898::DEBUG::2012-11-08 16:52:51,353::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: moving from state init -> state preparing
>Thread-9898::DEBUG::2012-11-08 16:52:51,353::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 2dc1c666-976e-423b-9cb1-6f98cca1fc6d acquire shared (120000)
>Thread-9898::DEBUG::2012-11-08 16:52:51,353::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9898::DEBUG::2012-11-08 16:52:51,353::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '2dc1c666-976e-423b-9cb1-6f98cca1fc6d'
>Thread-9898::DEBUG::2012-11-08 16:52:51,353::resource::524::irs::Owner 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9898::DEBUG::2012-11-08 16:52:51,354::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9898::DEBUG::2012-11-08 16:52:51,354::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: ref 1 aborting False
>Thread-9898::DEBUG::2012-11-08 16:52:51,354::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00471997261047', 'lastCheck': 1352393563.235297, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00688815116882', 'lastCheck': 1352393563.2794721, 'valid': True, 'code': 0}}
>Thread-9898::DEBUG::2012-11-08 16:52:51,354::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: moving from state preparing -> state finished
>Thread-9898::DEBUG::2012-11-08 16:52:51,354::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9a490>]
>Thread-9898::DEBUG::2012-11-08 16:52:51,355::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 2dc1c666-976e-423b-9cb1-6f98cca1fc6d releasing
>Thread-9898::DEBUG::2012-11-08 16:52:51,355::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9898::DEBUG::2012-11-08 16:52:51,355::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9898::DEBUG::2012-11-08 16:52:51,355::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9898::DEBUG::2012-11-08 16:52:51,355::resource::503::irs::Owner 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9a490> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9a490>'])
>Thread-9898::DEBUG::2012-11-08 16:52:51,355::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9898::DEBUG::2012-11-08 16:52:51,356::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9898::DEBUG::2012-11-08 16:52:51,356::task::577::irs::Task 2dc1c666-976e-423b-9cb1-6f98cca1fc6d: ref 0 aborting False
>Thread-9898::INFO::2012-11-08 16:52:51,356::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00471997261047', 'lastCheck': 1352393563.235297, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00688815116882', 'lastCheck': 1352393563.2794721, 'valid': True, 'code': 0}}
>Thread-9904::INFO::2012-11-08 16:53:01,449::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9904::DEBUG::2012-11-08 16:53:01,450::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: moving from state init -> state preparing
>Thread-9904::DEBUG::2012-11-08 16:53:01,450::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 71039ebb-20ad-4945-9c10-558e45be4295 acquire shared (120000)
>Thread-9904::DEBUG::2012-11-08 16:53:01,450::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9904::DEBUG::2012-11-08 16:53:01,450::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '71039ebb-20ad-4945-9c10-558e45be4295'
>Thread-9904::DEBUG::2012-11-08 16:53:01,450::resource::524::irs::Owner 71039ebb-20ad-4945-9c10-558e45be4295: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9904::DEBUG::2012-11-08 16:53:01,451::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9904::DEBUG::2012-11-08 16:53:01,451::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: ref 1 aborting False
>Thread-9904::DEBUG::2012-11-08 16:53:01,451::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00375699996948', 'lastCheck': 1352393573.239702, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00395917892456', 'lastCheck': 1352393573.2839141, 'valid': True, 'code': 0}}
>Thread-9904::DEBUG::2012-11-08 16:53:01,451::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: moving from state preparing -> state finished
>Thread-9904::DEBUG::2012-11-08 16:53:01,451::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9a410>]
>Thread-9904::DEBUG::2012-11-08 16:53:01,452::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 71039ebb-20ad-4945-9c10-558e45be4295 releasing
>Thread-9904::DEBUG::2012-11-08 16:53:01,452::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9904::DEBUG::2012-11-08 16:53:01,452::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9904::DEBUG::2012-11-08 16:53:01,452::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9904::DEBUG::2012-11-08 16:53:01,452::resource::503::irs::Owner 71039ebb-20ad-4945-9c10-558e45be4295: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9a410> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9a410>'])
>Thread-9904::DEBUG::2012-11-08 16:53:01,452::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9904::DEBUG::2012-11-08 16:53:01,453::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9904::DEBUG::2012-11-08 16:53:01,453::task::577::irs::Task 71039ebb-20ad-4945-9c10-558e45be4295: ref 0 aborting False
>Thread-9904::INFO::2012-11-08 16:53:01,453::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00375699996948', 'lastCheck': 1352393573.239702, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00395917892456', 'lastCheck': 1352393573.2839141, 'valid': True, 'code': 0}}
>Thread-5005::DEBUG::2012-11-08 16:53:14,667::guestIF::261::vds.vmlog.ceda1c63-d522-4add-bd81-8f0647a8fe9e::Guest connection timed out
>Thread-9910::INFO::2012-11-08 16:53:16,558::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9910::DEBUG::2012-11-08 16:53:16,558::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: moving from state init -> state preparing
>Thread-9910::DEBUG::2012-11-08 16:53:16,559::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: bcc30957-1ef2-4f55-a4be-73079460a4c7 acquire shared (120000)
>Thread-9910::DEBUG::2012-11-08 16:53:16,559::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9910::DEBUG::2012-11-08 16:53:16,559::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to 'bcc30957-1ef2-4f55-a4be-73079460a4c7'
>Thread-9910::DEBUG::2012-11-08 16:53:16,559::resource::524::irs::Owner bcc30957-1ef2-4f55-a4be-73079460a4c7: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9910::DEBUG::2012-11-08 16:53:16,559::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9910::DEBUG::2012-11-08 16:53:16,559::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: ref 1 aborting False
>Thread-9910::DEBUG::2012-11-08 16:53:16,560::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00366020202637', 'lastCheck': 1352393593.2463491, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00399899482727', 'lastCheck': 1352393593.2916989, 'valid': True, 'code': 0}}
>Thread-9910::DEBUG::2012-11-08 16:53:16,560::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: moving from state preparing -> state finished
>Thread-9910::DEBUG::2012-11-08 16:53:16,560::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9aa50>]
>Thread-9910::DEBUG::2012-11-08 16:53:16,560::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: bcc30957-1ef2-4f55-a4be-73079460a4c7 releasing
>Thread-9910::DEBUG::2012-11-08 16:53:16,560::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9910::DEBUG::2012-11-08 16:53:16,561::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9910::DEBUG::2012-11-08 16:53:16,561::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9910::DEBUG::2012-11-08 16:53:16,561::resource::503::irs::Owner bcc30957-1ef2-4f55-a4be-73079460a4c7: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9aa50> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9aa50>'])
>Thread-9910::DEBUG::2012-11-08 16:53:16,561::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9910::DEBUG::2012-11-08 16:53:16,561::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9910::DEBUG::2012-11-08 16:53:16,561::task::577::irs::Task bcc30957-1ef2-4f55-a4be-73079460a4c7: ref 0 aborting False
>Thread-9910::INFO::2012-11-08 16:53:16,562::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00366020202637', 'lastCheck': 1352393593.2463491, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00399899482727', 'lastCheck': 1352393593.2916989, 'valid': True, 'code': 0}}
>Thread-9916::INFO::2012-11-08 16:53:26,653::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9916::DEBUG::2012-11-08 16:53:26,654::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: moving from state init -> state preparing
>Thread-9916::DEBUG::2012-11-08 16:53:26,654::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: c885951d-3a2d-497d-a17f-7c8c510ea736 acquire shared (120000)
>Thread-9916::DEBUG::2012-11-08 16:53:26,654::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9916::DEBUG::2012-11-08 16:53:26,654::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to 'c885951d-3a2d-497d-a17f-7c8c510ea736'
>Thread-9916::DEBUG::2012-11-08 16:53:26,654::resource::524::irs::Owner c885951d-3a2d-497d-a17f-7c8c510ea736: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9916::DEBUG::2012-11-08 16:53:26,654::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9916::DEBUG::2012-11-08 16:53:26,655::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: ref 1 aborting False
>Thread-9916::DEBUG::2012-11-08 16:53:26,655::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00375699996948', 'lastCheck': 1352393603.2508161, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00411009788513', 'lastCheck': 1352393603.2961791, 'valid': True, 'code': 0}}
>Thread-9916::DEBUG::2012-11-08 16:53:26,655::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: moving from state preparing -> state finished
>Thread-9916::DEBUG::2012-11-08 16:53:26,655::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9aad0>]
>Thread-9916::DEBUG::2012-11-08 16:53:26,655::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: c885951d-3a2d-497d-a17f-7c8c510ea736 releasing
>Thread-9916::DEBUG::2012-11-08 16:53:26,656::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9916::DEBUG::2012-11-08 16:53:26,656::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9916::DEBUG::2012-11-08 16:53:26,656::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9916::DEBUG::2012-11-08 16:53:26,656::resource::503::irs::Owner c885951d-3a2d-497d-a17f-7c8c510ea736: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9aad0> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9aad0>'])
>Thread-9916::DEBUG::2012-11-08 16:53:26,656::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9916::DEBUG::2012-11-08 16:53:26,657::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9916::DEBUG::2012-11-08 16:53:26,657::task::577::irs::Task c885951d-3a2d-497d-a17f-7c8c510ea736: ref 0 aborting False
>Thread-9916::INFO::2012-11-08 16:53:26,657::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00375699996948', 'lastCheck': 1352393603.2508161, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00411009788513', 'lastCheck': 1352393603.2961791, 'valid': True, 'code': 0}}
>Thread-9924::INFO::2012-11-08 16:53:36,749::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9924::DEBUG::2012-11-08 16:53:36,749::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: moving from state init -> state preparing
>Thread-9924::DEBUG::2012-11-08 16:53:36,749::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: eb65c58f-2cf2-492d-9b45-cabf5cb1ec06 acquire shared (120000)
>Thread-9924::DEBUG::2012-11-08 16:53:36,749::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9924::DEBUG::2012-11-08 16:53:36,750::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to 'eb65c58f-2cf2-492d-9b45-cabf5cb1ec06'
>Thread-9924::DEBUG::2012-11-08 16:53:36,750::resource::524::irs::Owner eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9924::DEBUG::2012-11-08 16:53:36,750::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9924::DEBUG::2012-11-08 16:53:36,750::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: ref 1 aborting False
>Thread-9924::DEBUG::2012-11-08 16:53:36,750::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00377297401428', 'lastCheck': 1352393613.2542059, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00401401519775', 'lastCheck': 1352393613.3004589, 'valid': True, 'code': 0}}
>Thread-9924::DEBUG::2012-11-08 16:53:36,751::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: moving from state preparing -> state finished
>Thread-9924::DEBUG::2012-11-08 16:53:36,751::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9ac90>]
>Thread-9924::DEBUG::2012-11-08 16:53:36,751::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: eb65c58f-2cf2-492d-9b45-cabf5cb1ec06 releasing
>Thread-9924::DEBUG::2012-11-08 16:53:36,751::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9924::DEBUG::2012-11-08 16:53:36,751::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9924::DEBUG::2012-11-08 16:53:36,751::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9924::DEBUG::2012-11-08 16:53:36,752::resource::503::irs::Owner eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9ac90> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9ac90>'])
>Thread-9924::DEBUG::2012-11-08 16:53:36,752::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9924::DEBUG::2012-11-08 16:53:36,752::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9924::DEBUG::2012-11-08 16:53:36,752::task::577::irs::Task eb65c58f-2cf2-492d-9b45-cabf5cb1ec06: ref 0 aborting False
>Thread-9924::INFO::2012-11-08 16:53:36,752::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00377297401428', 'lastCheck': 1352393613.2542059, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00401401519775', 'lastCheck': 1352393613.3004589, 'valid': True, 'code': 0}}
>Thread-5006::INFO::2012-11-08 16:53:41,105::dispatcher::95::irs::Run and protect: getVolumeSize, args: ( sdUUID=756f1734-2600-456f-a4b1-4b6256a83316 spUUID=34eb6fe7-fee0-451a-8528-1829edf060de imgUUID=bcf6d4d2-d52b-493b-ab28-915e26c3b03d volUUID=88df524e-8276-407a-8426-80b7d54be180)
>Thread-5006::DEBUG::2012-11-08 16:53:41,105::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: moving from state init -> state preparing
>Thread-5006::INFO::2012-11-08 16:53:41,105::sp::1385::irs::(StoragePool.getDomains) Get storage pool domains: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': 'Active', '756f1734-2600-456f-a4b1-4b6256a83316': 'Active'}
>Thread-5006::INFO::2012-11-08 16:53:41,105::fileSD::214::irs::(FileStorageDomain.validate) sdUUID=756f1734-2600-456f-a4b1-4b6256a83316
>Thread-5006::DEBUG::2012-11-08 16:53:41,105::misc::100::irs::'/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv1_pstehlik_nfs02/756f1734-2600-456f-a4b1-4b6256a83316/dom_md/metadata' (cwd None)
>Thread-5006::DEBUG::2012-11-08 16:53:41,125::misc::123::irs::SUCCESS: <err> = '1+1 records in\n1+1 records out\n532 bytes (532 B) copied, 0.000826 seconds, 644 kB/s\n'; <rc> = 0
>Thread-5006::DEBUG::2012-11-08 16:53:41,126::metadata::89::irs::metadata.__validate() __cksum(md) = edfd6699dc1a1ddc9b3037ed9b484606660eccb4
>Thread-5006::DEBUG::2012-11-08 16:53:41,126::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 8e17f91d-60a5-4fd4-8460-763925bf6edc acquire shared (120000)
>Thread-5006::DEBUG::2012-11-08 16:53:41,126::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-5006::DEBUG::2012-11-08 16:53:41,126::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '8e17f91d-60a5-4fd4-8460-763925bf6edc'
>Thread-5006::DEBUG::2012-11-08 16:53:41,127::resource::524::irs::Owner 8e17f91d-60a5-4fd4-8460-763925bf6edc: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-5006::DEBUG::2012-11-08 16:53:41,127::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-5006::DEBUG::2012-11-08 16:53:41,127::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: ref 1 aborting False
>Thread-5006::DEBUG::2012-11-08 16:53:41,127::fileVolume::447::irs::validate image bcf6d4d2-d52b-493b-ab28-915e26c3b03d path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:53:41,129::fileVolume::483::irs::validate path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:53:41,132::fileVolume::447::irs::validate image bcf6d4d2-d52b-493b-ab28-915e26c3b03d path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:53:41,132::fileVolume::483::irs::validate path for 88df524e-8276-407a-8426-80b7d54be180
>Thread-5006::DEBUG::2012-11-08 16:53:41,134::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: finished: {'truesize': '2962411520', 'apparentsize': '7516192768'}
>Thread-5006::DEBUG::2012-11-08 16:53:41,134::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: moving from state preparing -> state finished
>Thread-5006::DEBUG::2012-11-08 16:53:41,134::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f84210>]
>Thread-5006::DEBUG::2012-11-08 16:53:41,135::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 8e17f91d-60a5-4fd4-8460-763925bf6edc releasing
>Thread-5006::DEBUG::2012-11-08 16:53:41,135::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-5006::DEBUG::2012-11-08 16:53:41,135::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-5006::DEBUG::2012-11-08 16:53:41,135::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-5006::DEBUG::2012-11-08 16:53:41,135::resource::503::irs::Owner 8e17f91d-60a5-4fd4-8460-763925bf6edc: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f84210> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f84210>'])
>Thread-5006::DEBUG::2012-11-08 16:53:41,135::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-5006::DEBUG::2012-11-08 16:53:41,136::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-5006::DEBUG::2012-11-08 16:53:41,136::task::577::irs::Task 8e17f91d-60a5-4fd4-8460-763925bf6edc: ref 0 aborting False
>Thread-5006::INFO::2012-11-08 16:53:41,136::dispatcher::101::irs::Run and protect: getVolumeSize, Return response: {'status': {'message': 'OK', 'code': 0}, 'truesize': '2962411520', 'apparentsize': '7516192768'}
>Thread-5005::DEBUG::2012-11-08 16:53:44,667::guestIF::261::vds.vmlog.ceda1c63-d522-4add-bd81-8f0647a8fe9e::Guest connection timed out
>Thread-9930::INFO::2012-11-08 16:53:46,856::dispatcher::95::irs::Run and protect: repoStats, args: ()
>Thread-9930::DEBUG::2012-11-08 16:53:46,856::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: moving from state init -> state preparing
>Thread-9930::DEBUG::2012-11-08 16:53:46,856::resource::298::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 1d86dd62-80ce-4329-bddd-045d8d47244b acquire shared (120000)
>Thread-9930::DEBUG::2012-11-08 16:53:46,856::resource::304::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de - lockstate free
>Thread-9930::DEBUG::2012-11-08 16:53:46,857::resource::239::irs::Resource 'Storage/34eb6fe7-fee0-451a-8528-1829edf060de': __granted shared to '1d86dd62-80ce-4329-bddd-045d8d47244b'
>Thread-9930::DEBUG::2012-11-08 16:53:46,857::resource::524::irs::Owner 1d86dd62-80ce-4329-bddd-045d8d47244b: _acquired Storage/34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9930::DEBUG::2012-11-08 16:53:46,857::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: _resourcesAcquired: Storage.34eb6fe7-fee0-451a-8528-1829edf060de (shared)
>Thread-9930::DEBUG::2012-11-08 16:53:46,857::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: ref 1 aborting False
>Thread-9930::DEBUG::2012-11-08 16:53:46,857::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: finished: {'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00457906723022', 'lastCheck': 1352393623.2593851, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00695490837097', 'lastCheck': 1352393623.30777, 'valid': True, 'code': 0}}
>Thread-9930::DEBUG::2012-11-08 16:53:46,857::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: moving from state preparing -> state finished
>Thread-9930::DEBUG::2012-11-08 16:53:46,858::resource::670::irs::Owner.releaseAll requests [] resources [<storage.resource.Resource object at 0x2aea15f9abd0>]
>Thread-9930::DEBUG::2012-11-08 16:53:46,858::resource::341::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: 1d86dd62-80ce-4329-bddd-045d8d47244b releasing
>Thread-9930::DEBUG::2012-11-08 16:53:46,858::resource::348::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: owners after release []
>Thread-9930::DEBUG::2012-11-08 16:53:46,858::resource::351::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: requests after release []
>Thread-9930::DEBUG::2012-11-08 16:53:46,858::resource::370::irs::Resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de: free lock
>Thread-9930::DEBUG::2012-11-08 16:53:46,859::resource::503::irs::Owner 1d86dd62-80ce-4329-bddd-045d8d47244b: _released Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9abd0> (['Storage/34eb6fe7-fee0-451a-8528-1829edf060de/<storage.resource.Resource object at 0x2aea15f9abd0>'])
>Thread-9930::DEBUG::2012-11-08 16:53:46,859::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: resourceReleased: Storage.34eb6fe7-fee0-451a-8528-1829edf060de
>Thread-9930::DEBUG::2012-11-08 16:53:46,859::resource::176::irs::resource Storage/34eb6fe7-fee0-451a-8528-1829edf060de after decref ref 0
>Thread-9930::DEBUG::2012-11-08 16:53:46,859::task::577::irs::Task 1d86dd62-80ce-4329-bddd-045d8d47244b: ref 0 aborting False
>Thread-9930::INFO::2012-11-08 16:53:46,859::dispatcher::101::irs::Run and protect: repoStats, Return response: {'status': {'message': 'OK', 'code': 0}, 'a5ed2e9f-8296-41de-8c41-0ffdbb8d0055': {'delay': '0.00457906723022', 'lastCheck': 1352393623.2593851, 'valid': True, 'code': 0}, '756f1734-2600-456f-a4b1-4b6256a83316': {'delay': '0.00695490837097', 'lastCheck': 1352393623.30777, 'valid': True, 'code': 0}}

Actions: View

Attachments on bug 874698: 640947 | 652729 | 652866 | 655164 | 655203