[Bugs] [Bug 1654370] Bitrot: Scrub status say file is corrupted even it was just created AND 'path' in the output is broken

bugzilla at redhat.com bugzilla at redhat.com
Wed Nov 28 15:53:37 UTC 2018 

https://bugzilla.redhat.com/show_bug.cgi?id=1654370



--- Comment #1 from david.spisla at iternity.com ---
fs-davids-c1-n1:/home/iternity # cat /var/log/glusterfs/scrub.log 
[2018-11-28 14:50:01.347943] I [MSGID: 118035]
[bit-rot-scrub.c:1313:br_scrubber_scale_up] 0-archive1-bit-rot-0: Scaling up
scrubbers [0 => 1]
[2018-11-28 14:50:01.348019] I [MSGID: 118048]
[bit-rot-scrub.c:1564:br_scrubber_log_option] 0-archive1-bit-rot-0: SCRUB
TUNABLES:: [Frequency: daily, Throttle: lazy]
[2018-11-28 14:50:01.348072] I [MSGID: 118031] [bit-rot.c:2054:init]
0-archive1-bit-rot-0: bit-rot xlator loaded in "SCRUBBER" mode
[2018-11-28 14:50:01.351245] I [socket.c:4167:ssl_setup_connection_params]
0-archive1-client-0: SSL support on the I/O path is ENABLED
[2018-11-28 14:50:01.351265] I [socket.c:4170:ssl_setup_connection_params]
0-archive1-client-0: SSL support for glusterd is ENABLED
[2018-11-28 14:50:01.351272] I [socket.c:4180:ssl_setup_connection_params]
0-archive1-client-0: using certificate depth 1
[2018-11-28 14:50:01.348178] I [MSGID: 101190]
[event-epoll.c:622:event_dispatch_epoll_worker] 0-epoll: Started thread with
index 2
[2018-11-28 14:50:01.356510] I [socket.c:4225:ssl_setup_connection_params]
0-archive1-client-0: failed to open /etc/ssl/dhparam.pem, DH ciphers are
disabled
[2018-11-28 14:50:01.357084] I [MSGID: 118035]
[bit-rot-scrub.c:1313:br_scrubber_scale_up] 0-archive2-bit-rot-0: Scaling up
scrubbers [0 => 1]
[2018-11-28 14:50:01.357148] I [MSGID: 118048]
[bit-rot-scrub.c:1564:br_scrubber_log_option] 0-archive2-bit-rot-0: SCRUB
TUNABLES:: [Frequency: daily, Throttle: lazy]
[2018-11-28 14:50:01.357564] I [MSGID: 118031] [bit-rot.c:2054:init]
0-archive2-bit-rot-0: bit-rot xlator loaded in "SCRUBBER" mode
[2018-11-28 14:50:01.357688] I [socket.c:4167:ssl_setup_connection_params]
0-archive2-client-0: SSL support on the I/O path is ENABLED
[2018-11-28 14:50:01.357697] I [socket.c:4170:ssl_setup_connection_params]
0-archive2-client-0: SSL support for glusterd is ENABLED
[2018-11-28 14:50:01.357702] I [socket.c:4180:ssl_setup_connection_params]
0-archive2-client-0: using certificate depth 1
[2018-11-28 14:50:01.357843] I [socket.c:4225:ssl_setup_connection_params]
0-archive2-client-0: failed to open /etc/ssl/dhparam.pem, DH ciphers are
disabled
[2018-11-28 14:50:01.358350] I [MSGID: 114020] [client.c:2354:notify]
0-archive1-client-0: parent translators are ready, attempting connect on
transport
[2018-11-28 14:50:01.358526] I [MSGID: 114020] [client.c:2354:notify]
0-archive2-client-0: parent translators are ready, attempting connect on
transport
Final graph:
+------------------------------------------------------------------------------+
  1: volume archive1-client-0
  2:     type protocol/client
  3:     option ping-timeout 42
  4:     option remote-host fs-davids-c1-n1
  5:     option remote-subvolume /gluster/brick1/glusterbrick
  6:     option transport-type socket
  7:     option transport.address-family inet
  8:     option username f79d8acf-5cbc-4066-b3a2-fefa79990db8
  9:     option password 9e2ab4e1-8de3-4b57-ac5e-4da52511e1de
 10:     option transport.socket.ssl-enabled true
 11: end-volume
 12:  
 13: volume archive1-bit-rot-0
 14:     type features/bit-rot
 15:     option scrubber true
 16:     option scrub-throttle lazy
 17:     option scrub-freq daily
 18:     subvolumes archive1-client-0
 19: end-volume
 20:  
 21: volume archive2-client-0
 22:     type protocol/client
 23:     option ping-timeout 42
 24:     option remote-host fs-davids-c1-n1
 25:     option remote-subvolume /gluster/brick2/glusterbrick
 26:     option transport-type socket
 27:     option transport.address-family inet
 28:     option username 1cde2f1b-24d2-4f8e-a3e6-aa0fd339df5c
 29:     option password 6dfe02e1-7c86-46d7-aaaf-6e4b96d89713
 30:     option transport.socket.ssl-enabled true
 31: end-volume
 32:  
 33: volume archive2-bit-rot-0
 34:     type features/bit-rot
 35:     option scrubber true
 36:     option scrub-throttle lazy
 37:     option scrub-freq daily
 38:     subvolumes archive2-client-0
 39: end-volume
 40:  
 41: volume scrub
 42:     type debug/io-stats
 43:     option log-level INFO
 44:     subvolumes archive1-bit-rot-0 archive2-bit-rot-0
 45: end-volume
 46:  
+------------------------------------------------------------------------------+
[2018-11-28 14:50:01.818206] I [rpc-clnt.c:2042:rpc_clnt_reconfig]
0-archive1-client-0: changing port to 49152 (from 0)
[2018-11-28 14:50:01.818540] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 14:50:01.818560] I [socket.c:4167:ssl_setup_connection_params]
0-archive1-client-0: SSL support on the I/O path is ENABLED
[2018-11-28 14:50:01.818566] I [socket.c:4170:ssl_setup_connection_params]
0-archive1-client-0: SSL support for glusterd is ENABLED
[2018-11-28 14:50:01.818572] I [socket.c:4180:ssl_setup_connection_params]
0-archive1-client-0: using certificate depth 1
[2018-11-28 14:50:01.818721] I [socket.c:4225:ssl_setup_connection_params]
0-archive1-client-0: failed to open /etc/ssl/dhparam.pem, DH ciphers are
disabled
[2018-11-28 14:50:01.857748] W [dict.c:1002:str_to_data]
(-->/usr/lib64/glusterfs/5.1/xlator/protocol/client.so(+0x3d6b4)
[0x7f18347506b4] -->/usr/lib64/libglusterfs.so.0(dict_set_str+0x16)
[0x7f183c0283f6] -->/usr/lib64/libglusterfs.so.0(str_to_data+0x60)
[0x7f183c0251c0] ) 0-dict: value is NULL [Invalid argument]
[2018-11-28 14:50:01.832490] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 14:50:01.857814] I [MSGID: 114006]
[client-handshake.c:1238:client_setvolume] 0-archive1-client-0: failed to set
process-name in handshake msg
[2018-11-28 14:50:01.858415] I [MSGID: 114046]
[client-handshake.c:1107:client_setvolume_cbk] 0-archive1-client-0: Connected
to archive1-client-0, attached to remote volume '/gluster/brick1/glusterbrick'.
[2018-11-28 14:50:01.860145] I [MSGID: 118039]
[bit-rot.c:1274:br_child_enaction] 0-archive1-bit-rot-0: Connected to brick
/gluster/brick1/glusterbrick..
[2018-11-28 14:50:01.860180] I [MSGID: 118038]
[bit-rot-scrub.c:962:br_fsscan_schedule] 0-archive1-bit-rot-0: Scrubbing is
scheduled to run at 2018-11-29 14:50:01
[2018-11-28 14:50:01.860196] I [MSGID: 118038]
[bit-rot-scrub.c:1913:wait_for_scrub_to_finish] 0-archive1-bit-rot-0: Waiting
for all children to start and finish scrub
[2018-11-28 14:50:01.897105] I [rpc-clnt.c:2042:rpc_clnt_reconfig]
0-archive2-client-0: changing port to 49153 (from 0)
[2018-11-28 14:50:01.897414] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 14:50:01.897441] I [socket.c:4167:ssl_setup_connection_params]
0-archive2-client-0: SSL support on the I/O path is ENABLED
[2018-11-28 14:50:01.897448] I [socket.c:4170:ssl_setup_connection_params]
0-archive2-client-0: SSL support for glusterd is ENABLED
[2018-11-28 14:50:01.897453] I [socket.c:4180:ssl_setup_connection_params]
0-archive2-client-0: using certificate depth 1
[2018-11-28 14:50:01.897605] I [socket.c:4225:ssl_setup_connection_params]
0-archive2-client-0: failed to open /etc/ssl/dhparam.pem, DH ciphers are
disabled
[2018-11-28 14:50:01.938013] W [dict.c:1002:str_to_data]
(-->/usr/lib64/glusterfs/5.1/xlator/protocol/client.so(+0x3d6b4)
[0x7f18347506b4] -->/usr/lib64/libglusterfs.so.0(dict_set_str+0x16)
[0x7f183c0283f6] -->/usr/lib64/libglusterfs.so.0(str_to_data+0x60)
[0x7f183c0251c0] ) 0-dict: value is NULL [Invalid argument]
[2018-11-28 14:50:01.938038] I [MSGID: 114006]
[client-handshake.c:1238:client_setvolume] 0-archive2-client-0: failed to set
process-name in handshake msg
[2018-11-28 14:50:01.943407] I [MSGID: 114046]
[client-handshake.c:1107:client_setvolume_cbk] 0-archive2-client-0: Connected
to archive2-client-0, attached to remote volume '/gluster/brick2/glusterbrick'.
[2018-11-28 14:50:01.945974] I [MSGID: 118039]
[bit-rot.c:1274:br_child_enaction] 0-archive2-bit-rot-0: Connected to brick
/gluster/brick2/glusterbrick..
[2018-11-28 14:50:01.946141] I [MSGID: 118038]
[bit-rot-scrub.c:962:br_fsscan_schedule] 0-archive2-bit-rot-0: Scrubbing is
scheduled to run at 2018-11-29 14:50:01
[2018-11-28 14:50:01.946166] I [MSGID: 118038]
[bit-rot-scrub.c:1913:wait_for_scrub_to_finish] 0-archive2-bit-rot-0: Waiting
for all children to start and finish scrub
[2018-11-28 14:50:05.454712] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:50:05.468263] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:50:05.655672] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 14:50:05.655745] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:50:05.668527] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:50:05.817169] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:50:05.833762] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:50:05.985347] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:50:06.000810] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:50:06.014248] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:50:06.031913] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:50:06.287688] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:50:06.300733] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
The message "E [MSGID: 101191] [event-epoll.c:671:event_dispatch_epoll_worker]
0-epoll: Failed to dispatch handler" repeated 6 times between [2018-11-28
14:50:05.655672] and [2018-11-28 14:50:06.300691]
[2018-11-28 14:57:31.505688] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:57:31.516034] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 14:57:31.516159] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:57:31.576154] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:57:31.589743] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:57:31.783030] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:57:31.815136] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 14:57:31.885691] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 14:57:31.896616] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
The message "E [MSGID: 101191] [event-epoll.c:671:event_dispatch_epoll_worker]
0-epoll: Failed to dispatch handler" repeated 9 times between [2018-11-28
14:57:31.516034] and [2018-11-28 14:57:31.896576]
[2018-11-28 15:07:36.246938] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 15:07:36.259385] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 15:07:36.311037] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 15:07:50.377803] I [bit-rot.c:1703:notify] 0-archive1-bit-rot-0:
BitRot scrub ondemand called
[2018-11-28 15:07:50.377828] I [MSGID: 118038]
[bit-rot-scrub.c:1105:br_fsscan_ondemand] 0-archive1-bit-rot-0: Ondemand
Scrubbing scheduled to run at 2018-11-28 15:07:51
[2018-11-28 15:07:50.389810] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 15:07:50.398858] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 15:07:51.603162] I [MSGID: 118044]
[bit-rot-scrub.c:618:br_scrubber_log_time] 0-archive1-bit-rot-0: Scrubbing
started at 2018-11-28 15:07:51
[2018-11-28 15:07:52.609932] A [MSGID: 118023]
[bit-rot-scrub.c:239:bitd_compare_ckum] 0-archive1-bit-rot-0: CORRUPTION
DETECTED: Object /data/file1.txt {Brick: /gluster/brick1/glusterbrick | GFID:
5d1fc972-cb11-4586-ac94-30a7cbc0690f}
[2018-11-28 15:07:52.609999] A [MSGID: 118024]
[bit-rot-scrub.c:260:bitd_compare_ckum] 0-archive1-bit-rot-0: Marking
/data/file1.txt [GFID: 5d1fc972-cb11-4586-ac94-30a7cbc0690f | Brick:
/gluster/brick1/glusterbrick] as corrupted..
[2018-11-28 15:07:53.611063] I [MSGID: 118045]
[bit-rot-scrub.c:622:br_scrubber_log_time] 0-archive1-bit-rot-0: Scrubbing
finished at 2018-11-28 15:07:53
[2018-11-28 15:07:53.611105] I [MSGID: 118038]
[bit-rot-scrub.c:1009:br_fsscan_activate] 0-archive1-bit-rot-0: Scrubbing is
rescheduled to run at 2018-11-29 15:07:53
[2018-11-28 15:07:53.611113] I [MSGID: 118038]
[bit-rot-scrub.c:1913:wait_for_scrub_to_finish] 0-archive1-bit-rot-0: Waiting
for all children to start and finish scrub
[2018-11-28 15:07:36.259349] E [MSGID: 101191]
[event-epoll.c:671:event_dispatch_epoll_worker] 0-epoll: Failed to dispatch
handler
[2018-11-28 15:08:03.304028] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 15:08:03.345501] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 15:18:37.925316] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 15:18:37.972416] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 15:19:01.922193] I [bit-rot.c:1703:notify] 0-archive1-bit-rot-0:
BitRot scrub ondemand called
[2018-11-28 15:19:01.922225] I [MSGID: 118038]
[bit-rot-scrub.c:1105:br_fsscan_ondemand] 0-archive1-bit-rot-0: Ondemand
Scrubbing scheduled to run at 2018-11-28 15:19:02
[2018-11-28 15:19:01.935622] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 15:19:02.000110] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing
[2018-11-28 15:19:03.213076] I [MSGID: 118044]
[bit-rot-scrub.c:618:br_scrubber_log_time] 0-archive1-bit-rot-0: Scrubbing
started at 2018-11-28 15:19:03
[2018-11-28 15:19:04.219146] E [MSGID: 114031]
[client-rpc-fops_v2.c:281:client4_0_open_cbk] 0-archive1-client-0: remote
operation failed. Path: /data/file1.txt (5d1fc972-cb11-4586-ac94-30a7cbc0690f)
[Input/output error]
[2018-11-28 15:19:04.219213] E [MSGID: 118008] [bit-rot.c:471:br_log_object]
0-archive1-bit-rot-0: open() failed on object
5d1fc972-cb11-4586-ac94-30a7cbc0690f [Input/output error]
[2018-11-28 15:19:05.222689] A [MSGID: 118023]
[bit-rot-scrub.c:239:bitd_compare_ckum] 0-archive1-bit-rot-0: CORRUPTION
DETECTED: Object /data/file2.txt {Brick: /gluster/brick1/glusterbrick | GFID:
cc9dc42f-d4ef-4ac7-8b1e-464e99dc371d}
[2018-11-28 15:19:05.222753] A [MSGID: 118024]
[bit-rot-scrub.c:260:bitd_compare_ckum] 0-archive1-bit-rot-0: Marking
/data/file2.txt [GFID: cc9dc42f-d4ef-4ac7-8b1e-464e99dc371d | Brick:
/gluster/brick1/glusterbrick] as corrupted..
[2018-11-28 15:19:06.223988] I [MSGID: 118045]
[bit-rot-scrub.c:622:br_scrubber_log_time] 0-archive1-bit-rot-0: Scrubbing
finished at 2018-11-28 15:19:06
[2018-11-28 15:19:06.224046] I [MSGID: 118038]
[bit-rot-scrub.c:1009:br_fsscan_activate] 0-archive1-bit-rot-0: Scrubbing is
rescheduled to run at 2018-11-29 15:19:06
[2018-11-28 15:19:06.224055] I [MSGID: 118038]
[bit-rot-scrub.c:1913:wait_for_scrub_to_finish] 0-archive1-bit-rot-0: Waiting
for all children to start and finish scrub
[2018-11-28 15:19:12.608391] I [glusterfsd-mgmt.c:58:mgmt_cbk_spec] 0-mgmt:
Volume file changed
[2018-11-28 15:19:12.623021] I [glusterfsd-mgmt.c:2005:mgmt_getspec_cbk]
0-glusterfs: No change in volfile,continuing

-- 
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
You are the Docs Contact for the bug.

More information about the Bugs mailing list