[ovirt-users] engine.log is looping with Volume XXX contains a apparently corrupt brick(s).

[Nir Soffer]

On Mon, Oct 12, 2015 at 11:14 AM, Nico <gluster at distran.org> wrote:
>
>
> Le 2015-10-12 09:59, Nir Soffer a écrit :
>
> On Sun, Oct 11, 2015 at 6:43 PM, Nico <gluster at distran.org> wrote:
>
> Recently, i built a small oVirt platform with 2 dedicated servers and
> GlusterFS to synch the VM storage.
> Bricks:
>
> Brick1: ovirt01:/gluster/ovirt
>
> Brick2: ovirt02:/gluster/ovirt
>
>
> This looks like replica 2 - this is not supported.
>
> You can use either replica 1 (testing) or replica 3 (production).
>
> But when i check /var/log/ovirt/engine.log on ovirt01, there are error in
> loop every 2 seconds:
>
> To understand such error we need to see the vdsm log.
>
> Nir
>
> Yeah it is replica 2 as i've only 2 dedicated servers.
>
> why are you saying it is not supported ? Through oVirt GUI, it is possible
> to create a Gluster Volume with 2 bricks in repllcate mode; i tried it also.

Yes, engine will let you use such volume in 3.5 - this is a bug. In 3.6 you will
not be able to use such setup.

replica 2 fails in a very bad way when one brick is down; the
application may get
stale data, and this breaks sanlock. You will be get stuck with spm
that cannot be
stopped and other fun stuff.

You don't want to go in this direction, and we will not be able to support that.

> here the last entries of vdsm.log

We need the whole file.

I suggest you file an ovirt bug and attach the full vdsm log file
showing the timeframe of
the error. Probably from the time you created the glusterfs domain.

Nir

>
>
>
> hread-167405::DEBUG::2015-10-12
> 10:12:20,132::stompReactor::163::yajsonrpc.StompServer::(send) Sending
> response
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,529::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`c887acfa-bd10-4dfb-9374-da607c133e68`::moving from state init -> state
> preparing
> Thread-55245::INFO::2015-10-12
> 10:12:22,530::logUtils::44::dispatcher::(wrapper) Run and protect:
> getVolumeSize(sdUUID='d44ee4b0-8d36-467a-9610-c682a618b698',
> spUUID='0ae7120a-430d-4534-9a7e-59c53fb2e804',
> imgUUID='3454b077-297b-4b89-b8ce-a77f6ec5d22e',
> volUUID='933da0b6-6a05-4e64-958a-e1c030cf5ddb', options=None)
> Thread-55245::INFO::2015-10-12
> 10:12:22,535::logUtils::47::dispatcher::(wrapper) Run and protect:
> getVolumeSize, Return response: {'truesize': '158983839744', 'apparentsize':
> '161061273600'}
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,535::task::1191::Storage.TaskManager.Task::(prepare)
> Task=`c887acfa-bd10-4dfb-9374-da607c133e68`::finished: {'truesize':
> '158983839744', 'apparentsize': '161061273600'}
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,535::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`c887acfa-bd10-4dfb-9374-da607c133e68`::moving from state preparing ->
> state finished
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,535::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll)
> Owner.releaseAll requests {} resources {}
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,536::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll)
> Owner.cancelAll requests {}
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,536::task::993::Storage.TaskManager.Task::(_decref)
> Task=`c887acfa-bd10-4dfb-9374-da607c133e68`::ref 0 aborting False
> Thread-55245::DEBUG::2015-10-12
> 10:12:22,545::libvirtconnection::143::root::(wrapper) Unknown libvirterror:
> ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata
> element is not present
> JsonRpc (StompReactor)::DEBUG::2015-10-12
> 10:12:23,138::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling
> message <StompFrame command='SEND'>
> JsonRpcServer::DEBUG::2015-10-12
> 10:12:23,139::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting
> for request
> Thread-167406::DEBUG::2015-10-12
> 10:12:23,142::stompReactor::163::yajsonrpc.StompServer::(send) Sending
> response
> Thread-37810::DEBUG::2015-10-12
> 10:12:24,194::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/ovirt01:_data_iso/5aec30fa-be8b-4f4e-832e-eafb6fa4a8e0/dom_md/metadata
> iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
> Thread-37810::DEBUG::2015-10-12
> 10:12:24,201::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n317 bytes (317 B) copied,
> 0.000131729 s, 2.4 MB/s\n'; <rc> = 0
> JsonRpc (StompReactor)::DEBUG::2015-10-12
> 10:12:26,148::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling
> message <StompFrame command='SEND'>
> JsonRpcServer::DEBUG::2015-10-12
> 10:12:26,149::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting
> for request
> Thread-167407::DEBUG::2015-10-12
> 10:12:26,151::stompReactor::163::yajsonrpc.StompServer::(send) Sending
> response
> VM Channels Listener::DEBUG::2015-10-12
> 10:12:26,972::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 35.
> Thread-30::DEBUG::2015-10-12
> 10:12:28,358::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/glusterSD/localhost:_ovirt/d44ee4b0-8d36-467a-9610-c682a618b698/dom_md/metadata
> iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
> Thread-30::DEBUG::2015-10-12
> 10:12:28,451::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n470 bytes (470 B) copied,
> 0.000152738 s, 3.1 MB/s\n'; <rc> = 0
> JsonRpc (StompReactor)::DEBUG::2015-10-12
> 10:12:29,157::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling
> message <StompFrame command='SEND'>
> JsonRpcServer::DEBUG::2015-10-12
> 10:12:29,252::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting
> for request
> Thread-167408::DEBUG::2015-10-12
> 10:12:29,254::stompReactor::163::yajsonrpc.StompServer::(send) Sending
> response
> JsonRpc (StompReactor)::DEBUG::2015-10-12
> 10:12:32,260::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling
> message <StompFrame command='SEND'>
> JsonRpcServer::DEBUG::2015-10-12
> 10:12:32,262::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting
> for request
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,264::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`7d55817b-a5c4-4c27-b2d5-e892ba645476`::moving from state init -> state
> preparing
> Thread-167409::INFO::2015-10-12
> 10:12:32,264::logUtils::44::dispatcher::(wrapper) Run and protect:
> repoStats(options=None)
> Thread-167409::INFO::2015-10-12
> 10:12:32,265::logUtils::47::dispatcher::(wrapper) Run and protect:
> repoStats, Return response: {u'd44ee4b0-8d36-467a-9610-c682a618b698':
> {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay':
> '0.000152738', 'lastCheck': '3.6', 'valid': True},
> u'5aec30fa-be8b-4f4e-832e-eafb6fa4a8e0': {'code': 0, 'actual': True,
> 'version': 0, 'acquired': True, 'delay': '0.000131729', 'lastCheck': '8.1',
> 'valid': True}}
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,265::task::1191::Storage.TaskManager.Task::(prepare)
> Task=`7d55817b-a5c4-4c27-b2d5-e892ba645476`::finished:
> {u'd44ee4b0-8d36-467a-9610-c682a618b698': {'code': 0, 'actual': True,
> 'version': 3, 'acquired': True, 'delay': '0.000152738', 'lastCheck': '3.6',
> 'valid': True}, u'5aec30fa-be8b-4f4e-832e-eafb6fa4a8e0': {'code': 0,
> 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000131729',
> 'lastCheck': '8.1', 'valid': True}}
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,265::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`7d55817b-a5c4-4c27-b2d5-e892ba645476`::moving from state preparing ->
> state finished
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,265::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll)
> Owner.releaseAll requests {} resources {}
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,265::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll)
> Owner.cancelAll requests {}
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,265::task::993::Storage.TaskManager.Task::(_decref)
> Task=`7d55817b-a5c4-4c27-b2d5-e892ba645476`::ref 0 aborting False
> Thread-167409::DEBUG::2015-10-12
> 10:12:32,268::stompReactor::163::yajsonrpc.StompServer::(send) Sending
> response
> JsonRpc (StompReactor)::DEBUG::2015-10-12
> 10:12:32,275::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling
> message <StompFrame command='SEND'>
> JsonRpcServer::DEBUG::2015-10-12
> 10:12:32,278::__init__::530::jsonrpc.JsonRpcServer::(serve_requests) Waiting
> for request
> Thread-167410::DEBUG::2015-10-12
> 10:12:32,283::stompReactor::163::yajsonrpc.StompServer::(send) Sending
> response
>
>
>
>