tatsuya6502
commented
11 years ago hibari1 - console.log
2013-03-30 03:01:05.421 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 SCAV: Updating locations for sequence 1 (true)
2013-03-30 03:01:06.144 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 SCAV: commonLogServer sequence 1: UpRes ok, 12623 updates
2013-03-30 03:01:15.782 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 SCAV: Updating locations for sequence 3 (true)
2013-03-30 03:01:16.386 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 SCAV: commonLogServer sequence 3: UpRes ok, 10017 updates
2013-03-30 03:01:26.235 [info] <0.596.0>@congestion_watcher_server:do_mark:233 mark: 20130330030126 [{0,4},{282,282},{900824,2357540}]
2013-03-30 03:01:29.376 [info] <0.25906.46>@gmt_hlog:spawn_sync_asyncly:1357 commonLogServer sync was 213 msec for 1 callers
2013-03-30 03:01:46.622 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 SCAV: Updating locations for sequence 4 (true)
2013-03-30 03:01:49.194 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 SCAV: commonLogServer sequence 4: UpRes ok, 38232 updates
2013-03-30 03:01:54.519 [info] <0.28395.46>@gmt_hlog:spawn_sync_asyncly:1357 commonLogServer sync was 312 msec for 1 callers
...
2013-03-30 03:11:14.029 [info] <0.5250.46>@brick_ets:make_info_log_fun:3558 Scavenger finished:
Options: [destructive,{skip_live_percentage_greater_than,90},{work_dir,"/scav/hibari1_scavenger"}]
Logs deleted without scavenging: 2 (24 bytes)
Logs scavenged: 21
Copied: hunks bytes errs = 763583 781908992 0
Reclaimed bytes = 308037249
...
2013-03-30 04:00:26.236 [info] <0.596.0>@congestion_watcher_server:do_mark:233 mark: 20130330040026 [{1,4},{277,285},{900824,2357540}]
2013-03-30 04:00:57.401 [warning] <0.31010.58>@brick_ets:bigdata_dir_get_val:2922 stability_test_ch3_b3: error {error,enoent} at 1 36210172
2013-03-30 04:00:57.403 [warning] <0.610.0>@brick_ets:sequence_file_is_bad_common:3022 Brick commonLogServer bad sequence file: seq 1 offset 36210172: rename data/brick/hlog.commonLogServer/s/000000000001.HLOG or data/brick/hlog.commonLogServer/2/2/-000000000001.HLOG to data/brick/hlog.commonLogServer/BAD-CHECKSUM/1.at.offset.36210172 failed: enoent
2013-03-30 04:00:57.405 [info] <0.769.0>@brick_ets:purge_recs_by_seqnum:2006 stability_test_ch3_b3: purging keys with sequence 1, size 259805
2013-03-30 04:00:57.407 [info] <0.783.0>@brick_ets:purge_recs_by_seqnum:2006 stability_test_ch1_b1: purging keys with sequence 1, size 368467
2013-03-30 04:00:57.408 [info] <0.758.0>@brick_ets:purge_recs_by_seqnum:2006 stability_test_ch4_b2: purging keys with sequence 1, size 347070
2013-03-30 04:00:57.818 [info] <0.769.0>@brick_server:do_common_log_sequence_file_is_bad:5555 common_log_sequence_file_is_bad: stability_test_ch3_b3: 1 purged keys for log 1
2013-03-30 04:00:57.897 [info] <0.758.0>@brick_server:do_common_log_sequence_file_is_bad:5555 common_log_sequence_file_is_bad: stability_test_ch4_b2: 0 purged keys for log 1
2013-03-30 04:00:57.900 [info] <0.783.0>@brick_server:do_common_log_sequence_file_is_bad:5555 common_log_sequence_file_is_bad: stability_test_ch1_b1: 1 purged keys for log 1
2013-03-30 04:00:58.340 [info] <0.615.0>@brick_mboxmon:handle_info:152 node 'basho_bench@127.0.0.1' down Extra [{nodedown_reason,connection_closed},{node_type,visible}]
2013-03-30 04:00:58.853 [error] <0.690.0>@brick_admin:run_client_monitor_procs:2171 Node 'basho_bench@127.0.0.1' application gdss_client is stopped
2013-03-30 04:00:58.855 [info] <0.530.0> alarm_handler: {set,{{client_node_down,'basho_bench@127.0.0.1'},"GDSS application is not running on this node."}}
2013-03-30 04:00:59.510 [info] <0.696.0>@brick_chainmon:set_all_chain_roles:1307 set_all_chain_roles: stability_test_ch1: top
2013-03-30 04:00:59.510 [info] <0.530.0>@brick_admin_event_h:handle_event:120 handle_event: {set_alarm,{{disk_error,{stability_test_ch1_b1,'hibari1@127.0.0.1'}},"Administrator intervention is required."}}
2013-03-30 04:00:59.510 [info] <0.530.0> alarm_handler: {set,{{disk_error,{stability_test_ch1_b1,'hibari1@127.0.0.1'}},"Administrator intervention is required."}}
2013-03-30 04:00:59.511 [info] <0.696.0>@brick_chainmon:set_all_chain_roles:1309 set_all_chain_roles: stability_test_ch1: brick read-only 1
2013-03-30 04:00:59.514 [info] <0.696.0>@brick_chainmon:set_all_chain_roles:1352 New head {stability_test_ch1_b2,'hibari2@127.0.0.1'}: ChainDownSerial 368037 /= ChainDownAcked -4242, reflushing log downstream
2013-03-30 04:00:59.516 [info] <0.696.0>@brick_chainmon:set_all_chain_roles:1360 New head {stability_test_ch1_b2,'hibari2@127.0.0.1'}: flush was ok
2013-03-30 04:00:59.516 [info] <0.645.0>@brick_admin:do_chain_status_change:1410 status_change: Chain stability_test_ch1 status degraded belongs to tab stability_test
2013-03-30 04:00:59.528 [info] <0.645.0>@brick_admin:do_spam_gh_to_all_nodes:1478 do_spam_gh_to_all_nodes: top
2013-03-30 04:00:59.529 [info] <0.645.0>@brick_admin:do_spam_gh_to_all_nodes:1488 do_spam_gh_to_all_nodes: minor_rev=74
2013-03-30 04:00:59.529 [info] <0.645.0>@brick_admin:do_chain_status_change:1410 status_change: Chain stability_test_ch1 status degraded belongs to tab stability_test
2013-03-30 04:00:59.542 [info] <0.645.0>@brick_admin:do_spam_gh_to_all_nodes:1478 do_spam_gh_to_all_nodes: top
2013-03-30 04:00:59.543 [info] <0.645.0>@brick_admin:do_spam_gh_to_all_nodes:1488 do_spam_gh_to_all_nodes: minor_rev=75
2013-03-30 04:00:59.697 [info] <0.698.0>@brick_chainmon:set_all_chain_roles:1307 set_all_chain_roles: stability_test_ch3: top
2013-03-30 04:00:59.697 [info] <0.530.0>@brick_admin_event_h:handle_event:120 handle_event: {set_alarm,{{disk_error,{stability_test_ch3_b3,'hibari1@127.0.0.1'}},"Administrator intervention is required."}}
2013-03-30 04:00:59.697 [info] <0.530.0> alarm_handler: {set,{{disk_error,{stability_test_ch3_b3,'hibari1@127.0.0.1'}},"Administrator intervention is required."}}
2013-03-30 04:00:59.697 [info] <0.698.0>@brick_chainmon:set_all_chain_roles:1309 set_all_chain_roles: stability_test_ch3: brick read-only 1
2013-03-30 04:00:59.701 [info] <0.698.0>@brick_chainmon:set_all_chain_roles:1352 New head {stability_test_ch3_b1,'hibari3@127.0.0.1'}: ChainDownSerial 259439 /= ChainDownAcked -4242, reflushing log downstream
2013-03-30 04:00:59.703 [info] <0.698.0>@brick_chainmon:set_all_chain_roles:1360 New head {stability_test_ch3_b1,'hibari3@127.0.0.1'}: flush was ok
2013-03-30 04:00:59.703 [info] <0.645.0>@brick_admin:do_chain_status_change:1410 status_change: Chain stability_test_ch3 status degraded belongs to tab stability_test
2013-03-30 04:00:59.715 [info] <0.645.0>@brick_admin:do_spam_gh_to_all_nodes:1478 do_spam_gh_to_all_nodes: top
2013-03-30 04:00:59.715 [info] <0.645.0>@brick_admin:do_spam_gh_to_all_nodes:1488 do_spam_gh_to_all_nodes: minor_rev=76
2013-03-30 04:00:59.716 [info] <0.645.0>@brick_admin:do_chain_status_change:1410 status_change: Chain stability_test_ch3 status degraded belongs to tab stability_test
This is a blocker issue.
This error occured while runnig a 8-hour stability test against 4-node Hibari 0.3.0 RC (Release Candidate). All Hibari nodes were running within one Solaris Zone-based SmartOS machine at Joyent Cloud. (Machine type: smartmachine medium 4GB RAM, 4 vCPUs)
Summary:
At 04:00, node
hibari1@127.0.0.0got the following bad sequence file error enoent on a common log file with sequence 1. That file was deleted by the scavenger between 03:01 and 03:11.hibair1@127.0.0.1was hosting 3 logical bricks and reported total 2 keys were purged by absence of log 1. It put affected bricks in read-only mode, and other brick servers took over the roles of the affected bricks. So there was no data loss in this particular case.The scavenger process was started at 3:00 and finished 3:11. It didn't report any problem including updating locations for log 1.
Conditions:
syncwrites = true{brick_scavenger_start_time, "03:00"}{brick_scavenger_temp_dir,"/scav/hibari1_scavenger"}{brick_scavenger_throttle_bytes, 2097152}{brick_skip_live_percentage_greater_than, 90}