2011-02-10 11:21:14: (message) mysql-proxy 0.8.1 started 2011-02-10 11:21:14: (debug) max open file-descriptors = 1024 2011-02-10 11:21:14.009: (message) [T0x9706008 chass]: Setting locale directory to /home/billy/mysql/mcm2/share/locale 2011-02-10 11:21:14.009: (message) [T0x9706008 chass]: Starting MySQL Cluster Manager 1.1.0 2011-02-10 11:21:14.009: (debug) [T0x9706008 chass@manager-plugin.c:461]: Initializing command queue 2011-02-10 11:21:14.010: (debug) [T0x9706008 chass@manager-xml.c:3479]: Initializing xml process definitions from /home/billy/mysql/mcm2/var/mysql_cluster_processdef.xml 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-plugin.c:467]: Initializing xml command definition file 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-commands.c:2766]: Mapping internal command handler(s) 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-commands.c:2770]: Mapping CLI command handler(s) 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-commands.c:2804]: Mapping command handlers completed 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option help added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option version added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option force added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option background added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option cluster added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option hosts added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option basedir added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option processhosts added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option configfile added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option include-defaults added as legal option 2011-02-10 11:21:14.014: (debug) [T0x9706008 chass@manager-parser.c:170]: Option operation added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option process added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option package added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option path added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option adminpassword added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option initial added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option set added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:170]: Option added added as legal option 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:181]: Option help added as legal option for all commands 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:181]: Option version added as legal option for all commands 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for list commands 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:257]: Command list commands added as legal command 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for create site 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:241]: Option hosts added as required option for create site 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:245]: Option hosts added as valid option for create site 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:257]: Command create site added as legal command 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for delete site 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for delete site 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:257]: Command delete site added as legal command 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for list sites 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:257]: Command list sites added as legal command 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for list hosts 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:257]: Command list hosts added as legal command 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for add package 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:241]: Option basedir added as required option for add package 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:245]: Option basedir added as valid option for add package 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for add package 2011-02-10 11:21:14.015: (debug) [T0x9706008 chass@manager-parser.c:230]: Option hosts added as legal option for add package 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command add package added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for delete package 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for delete package 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option hosts added as legal option for delete package 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command delete package added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for list packages 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command list packages added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for create cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:241]: Option package added as required option for create cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:245]: Option package added as valid option for create cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:241]: Option processhosts added as required option for create cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:245]: Option processhosts added as valid option for create cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for create cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command create cluster added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for delete cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for delete cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for delete cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command delete cluster added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for start cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for start cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for start cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command start cluster added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for stop cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for stop cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for stop cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command stop cluster added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for restart cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for restart cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for restart cluster 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:257]: Command restart cluster added as legal command 2011-02-10 11:21:14.016: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for upgrade cluster 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:241]: Option package added as required option for upgrade cluster 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:245]: Option package added as valid option for upgrade cluster 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for upgrade cluster 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for upgrade cluster 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command upgrade cluster added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for list clusters 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command list clusters added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for get 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option include-defaults added as legal option for get 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command get added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for set 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for set 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for set 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command set added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for reset 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for reset 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for reset 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command reset added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for show status 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option cluster added as legal option for show status 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option operation added as legal option for show status 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option process added as legal option for show status 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command show status added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for stop process 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for stop process 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for stop process 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:257]: Command stop process added as legal command 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for start process 2011-02-10 11:21:14.017: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for start process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option initial added as legal option for start process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option added added as legal option for start process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for start process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:257]: Command start process added as legal command 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for list processes 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:257]: Command list processes added as legal command 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for change process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for change process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:257]: Command change process added as legal command 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for add hosts 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:241]: Option hosts added as required option for add hosts 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:245]: Option hosts added as valid option for add hosts 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:257]: Command add hosts added as legal command 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:218]: Handler function pointer found for add process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option processhosts added as legal option for add process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option set added as legal option for add process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option background added as legal option for add process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:230]: Option force added as legal option for add process 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:257]: Command add process added as legal command 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:321]: Parsing completed: 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:322]: 18 option definitions 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:323]: 2 option definitions all cmds 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:324]: 25 command definitions 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-parser.c:325]: 33 command handlers mapped 2011-02-10 11:21:14.018: (debug) [T0x9706008 chass@manager-plugin.c:476]: failed to setsid 1: Operation not permitted 2011-02-10 11:21:14.019: (debug) [T0x9706008 chass@xcom_vpman.c:412]: replace_app_data_single *(&ctxt->outgoing.p)=NULL msg_count(*(&ctxt->outgoing.p))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.019: (debug) [T0x9706008 chass@xcom_vpman.c:416]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.019: (debug) [T0x9706008 chass@xcom_vpman.c:417]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.019: (debug) [T0x9706008 chass@xcom_vpman.c:418]: replace_app_data_single *(&ctxt->node_group)=NULL msg_count(*(&ctxt->node_group))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.019: (debug) [T0x9706008 chass@xcom_vpman.c:419]: replace_app_data_single *(&ctxt->prev_node_group)=NULL msg_count(*(&ctxt->prev_node_group))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.020: (debug) [T0x9706008 chass@xcom_vpman.c:440]: replace_app_data_single *(&ctxt->input_buffer)=NULL msg_count(*(&ctxt->input_buffer))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.020: (debug) [T0x9706008 chass@xcom_vpman.c:441]: replace_app_data_single *(&ctxt->delayed_mess)=NULL msg_count(*(&ctxt->delayed_mess))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.020: (message) [T0x9706008 chass]: init_recovery_sema 2011-02-10 11:21:14.020: (message) [T0x9706008 chass]: set_recovery_sema 2011-02-10 11:21:14.020: (message) [T0x9706008 chass]: Store initialized at /home/billy/mysq/mcm2/manager/rep/ 2011-02-10 11:21:14.028: (debug) [T0x9706008 chass@manager-plugin.c:525]: Initializing client socket 2011-02-10 11:21:14.028: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5509]: init cluster manager, starts mainloop thread 2011-02-10 11:21:14.028: (message) [T0x971fdf0 CMGR ]: Starting recovery 2011-02-10 11:21:14.028: (debug) [T0x9706008 chass@message-broker.c:715]: Setting up command queue pollinginterval_sec=0x1(1) 2011-02-10 11:21:14.028: (message) [T0x971fdf0 CMGR ]: cluster manager started 2011-02-10 11:21:14.122: (debug) vpfsm_process_message executed_key {0 0} last_key {0 0} 2011-02-10 11:21:14.122: (debug) incoming message app_data (nil) count 0 2011-02-10 11:21:14.122: (debug) deliver message status 0 app_data (nil) count 0 2011-02-10 11:21:14.122: (debug) [T0x9706008 chass@message-broker.c:275]: message_broker(): putting view msg in cluster manager queue 2011-02-10 11:21:14.122: (debug) done_reload msg_index -1 msg_list.vp_count_array_len 0 2011-02-10 11:21:14.123: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.123: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:21:14.123: (debug) vp count {0 0} node 0 node 0 2011-02-10 11:21:14.123: (message) [T0x9706008 chass]: Node set 2011-02-10 11:21:14.123: (debug) 2011-02-10 11:21:14.123: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2af9(11001) mgr_view_msg 2011-02-10 11:21:14.123: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 1297336874.123264 2011-02-10 11:21:14.123: (debug) [T0x971fdf0 CMGR ]: req_id 0 Start working on message @ 0 : mgr_view_msg 2011-02-10 11:21:14.123: (debug) [T0x971fdf0 CMGR ]: req_id 0 Finished working on message 0 2011-02-10 11:21:14.123: (debug) [T0x9706008 chass@xcom_vpman.c:4150]: replace_app_data_single *(&a)=0xb6d012c8 msg_count(*(&a))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:21:14.123: (message) [T0x9706008 chass]: end_recovery 2011-02-10 11:21:38.334: (debug) [T0x9706008 chass@manager-plugin.c:225]: Client connection accepted in state CON_STATE_SEND_AUTH_RESULT 2011-02-10 11:21:38.334: (debug) [T0x9706008 chass@manager-plugin.c:227]: New connection from 127.0.0.1:43662 con=0xb6d02278 2011-02-10 11:21:38.334: (debug) [T0x9706008 chass@manager-commands.c:323]: handle_command() : select @@version_comment limit 1 2011-02-10 11:22:08.639: (message) [T0x9706008 chass]: Received command : create site --hosts=192.168.1.5 mysitel 2011-02-10 11:22:08.639: (debug) [T0x9706008 chass@manager-commands.c:2404]: escaped_cmdline=`create site --hosts=192.168.1.5 mysitel' 2011-02-10 11:22:08.639: (debug) [T0x9706008 chass@manager-commands.c:2517]: Adding option to commands option list : hosts 2011-02-10 11:22:08.639: (debug) [T0x9706008 chass@manager-commands.c:2523]: Adding operand to commands operand list : mysitel 2011-02-10 11:22:08.639: (debug) [T0x9706008 chass@manager-commands.c:1732]: handle_create_site() 2011-02-10 11:22:08.640: (debug) [T0x9706008 chass@manager-commands.c:1754]: Will distribute site to the following hosts: 2011-02-10 11:22:08.640: (debug) [T0x9706008 chass@manager-commands.c:1774]: 192.168.1.5 2011-02-10 11:22:08.640: (message) [T0x9706008 chass]: Handling request id 1 2011-02-10 11:22:08.640: (debug) [T0x9706008 chass@manager-commands.c:1781]: INIT_CLIENT_ADDRESS &msg->client_address=127.0.0.1:43662 req_id 1 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 01 00 00 00 } 2011-02-10 11:22:08.640: (debug) [T0x9706008 chass@message-broker.c:155]: message_broker(): putting site in cluster manager queue 2011-02-10 11:22:08.640: (debug) [T0x9706008 chass@manager-commands.c:1787]: handle_create_site() done. 2011-02-10 11:22:08.640: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x1(1) api_create_site 2011-02-10 11:22:08.640: (message) [T0x971fdf0 CMGR ]: req_id 1 Start working on message @ 0 : api_create_site 2011-02-10 11:22:08.640: (debug) [T0x971fdf0 CMGR @cluster-manager.c:551]: handling api site 2011-02-10 11:22:08.641: (debug) [T0x971fdf0 CMGR @cluster-manager.c:577]: I am g_get_host_name()=`billy-laptop' 2011-02-10 11:22:08.641: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1935]: Checking site for myhost site->sitename=`mysitel' 2011-02-10 11:22:08.641: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1944]: h->hostname=`192.168.1.5' 2011-02-10 11:22:08.641: (debug) [T0x971fdf0 CMGR @xcom_utils.c:423]: xcom_myhost_match hostaddress=`192.168.1.5' 2011-02-10 11:22:08.642: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1946]: myhost is included in sitelist 2011-02-10 11:22:08.642: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1973]: Checking site mysitel hostnames 2011-02-10 11:22:08.642: (debug) [T0x971fdf0 CMGR @cluster-manager.c:494]: xcom_async_send_msg_unlocked im 0xb6d02048 2011-02-10 11:22:08.642: (message) [T0x971fdf0 CMGR ]: req_id 1 Finished working on message 0 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:304]: replace_app_data_single *(&ctxt->node_group)=NULL msg_count(*(&ctxt->node_group))=0x0(0) a=0x97163b8 msg_count(a)=0x1(1) 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x97163b8 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9716438 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:4150]: replace_app_data_single *(&a)=0x97164c8 msg_count(*(&a))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9716660 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x97163b8 msg_count(out_msg)=0x3(3) 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb6d020d8 msg_count(a)=0x3(3) 2011-02-10 11:22:08.739: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb6d02a58 msg_count(a)=0x2(2) 2011-02-10 11:22:08.740: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb6d01e68 msg_count(a)=0x1(1) 2011-02-10 11:22:08.740: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x97163b8 msg_count(*(&ctxt->outgoing.p))=0x3(3) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.740: (debug) vpfsm_process_message executed_key {0 0} last_key {0 0} 2011-02-10 11:22:08.740: (debug) incoming message app_data 0xb6d020d8 count 3 app_data 0xb6d020d8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next 0xb6d02a58 app_data 0xb6d02a58 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next 0xb6d01e68 app_data 0xb6d01e68 group_id 94aaf91c vp count {0 1} node 0 app_key {0 3} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 172 next (nil) 2011-02-10 11:22:08.740: (debug) app_data 0xb6d020d8 count 1 app_data 0xb6d020d8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) update_last_key setting last_key to {0 1} 2011-02-10 11:22:08.740: (debug) before_boot {0 0} 2011-02-10 11:22:08.740: (debug) last message repeated 1 times 2011-02-10 11:22:08.740: (debug) insert_log next_in -1 log_min {0 0} log_max {0 0} a->key {0 1} 2011-02-10 11:22:08.740: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb6d020d8 msg_count(a)=0x1(1) 2011-02-10 11:22:08.740: (debug) replace_app_data_single location target 0x9738318 app_data (nil) count 0 source 0xb6d020d8 app_data 0xb6d020d8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.740: (debug) lookup_log_index key {0 1} returns 0 2011-02-10 11:22:08.740: (debug) lookup_log returns 0x9715f78 lookup_log_index key {0 2} returns -1 2011-02-10 11:22:08.740: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=NULL msg_count(*(&ctxt->prev_node_group))=0x0(0) ctxt->node_group=0xb6d024a8 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:08.741: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data (nil) count 0 source 0xb6d024a8 app_data 0xb6d024a8 group_id 94aaf91c vp count {0 0} node 0 app_key {0 0} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.741: (debug) nging group id from 94aaf91c to 94aaf91c 2011-02-10 11:22:08.741: (debug) last message repeated 1 times 2011-02-10 11:22:08.741: (debug) do_install_node_group node_group ctxt->node_group 0xb6d024a8 a 0xb6d020d8 2011-02-10 11:22:08.741: (debug) setting node to 0 2011-02-10 11:22:08.741: (debug) [T0x9706008 chass@xcom_vpman.c:304]: replace_app_data_single *(&ctxt->node_group)=0xb6d024a8 msg_count(*(&ctxt->node_group))=0x1(1) a=0xb6d020d8 msg_count(a)=0x1(1) 2011-02-10 11:22:08.741: (debug) replace_app_data_single location target 0x972e60c app_data 0xb6d024a8 count 1 app_data 0xb6d024a8 group_id 94aaf91c vp count {0 0} node 0 app_key {0 0} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) source 0xb6d020d8 app_data 0xb6d020d8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.741: (debug) setting maxnodes to 1 2011-02-10 11:22:08.741: (debug) onfsm_create 192.168.1.5:1862 2011-02-10 11:22:08.741: (debug) set_connections c 0x9722b48 2011-02-10 11:22:08.741: (debug) deliver message status 0 app_data 0xb6d020d8 count 1 app_data 0xb6d020d8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.741: (debug) [T0x9706008 chass@message-broker.c:275]: message_broker(): putting view msg in cluster manager queue 2011-02-10 11:22:08.741: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb6d020d8 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.741: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5694]: node_list changed content 2011-02-10 11:22:08.742: (debug) executed xcom_set_group message replace_app_data_single location target 0xbff57504 app_data 0xb6d020d8 count 1 app_data 0xb6d020d8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) source (nil) 2011-02-10 11:22:08.742: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2af9(11001) mgr_view_msg 2011-02-10 11:22:08.742: (debug) app_data 0xb6d02a58 count 1 app_data 0xb6d02a58 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) update_last_key setting last_key to {0 2} 2011-02-10 11:22:08.742: (debug) [T0x971fdf0 CMGR ]: req_id 0 Start working on message @ 1 : mgr_view_msg 2011-02-10 11:22:08.742: (message) [T0x9706008 chass]: end_recovery 2011-02-10 11:22:08.742: (debug) finished log, sending delayed messages 2011-02-10 11:22:08.742: (debug) before_boot {0 1} 2011-02-10 11:22:08.742: (debug) last message repeated 1 times 2011-02-10 11:22:08.742: (debug) [T0x971fdf0 CMGR ]: req_id 0 Finished working on message 1 2011-02-10 11:22:08.742: (debug) insert_log next_in 0 log_min {0 1} log_max {0 1} a->key {0 2} 2011-02-10 11:22:08.742: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb6d02a58 msg_count(a)=0x1(1) 2011-02-10 11:22:08.742: (debug) replace_app_data_single location target 0x973831c app_data (nil) count 0 source 0xb6d02a58 app_data 0xb6d02a58 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.742: (debug) lookup_log_index key {0 2} returns 1 2011-02-10 11:22:08.742: (debug) lookup_log returns 0xb6d020d8 lookup_log_index key {0 3} returns -1 2011-02-10 11:22:08.742: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9716e00 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0x9715ff0 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:08.743: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9716e00 count 1 app_data 0x9716e00 group_id 94aaf91c vp count {0 0} node 0 app_key {0 0} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) source 0x9715ff0 app_data 0x9715ff0 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.743: (debug) nging group id from 94aaf91c to 94aaf91c 2011-02-10 11:22:08.743: (debug) last message repeated 1 times 2011-02-10 11:22:08.743: (debug) do_install_node_group node_group ctxt->node_group 0x9715ff0 a 0xb6d02a58 2011-02-10 11:22:08.743: (debug) setting node to 0 2011-02-10 11:22:08.743: (debug) [T0x9706008 chass@xcom_vpman.c:304]: replace_app_data_single *(&ctxt->node_group)=0x9715ff0 msg_count(*(&ctxt->node_group))=0x1(1) a=0xb6d02a58 msg_count(a)=0x1(1) 2011-02-10 11:22:08.743: (debug) replace_app_data_single location target 0x972e60c app_data 0x9715ff0 count 1 app_data 0x9715ff0 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) source 0xb6d02a58 app_data 0xb6d02a58 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.743: (debug) setting maxnodes to 1 2011-02-10 11:22:08.743: (debug) onfsm_create 192.168.1.5:1862 2011-02-10 11:22:08.743: (debug) set_connections c 0xb6d024c8 2011-02-10 11:22:08.743: (debug) deliver message status 0 app_data 0xb6d02a58 count 1 app_data 0xb6d02a58 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.743: (debug) [T0x9706008 chass@message-broker.c:275]: message_broker(): putting view msg in cluster manager queue 2011-02-10 11:22:08.743: (debug) executed message {0 2} 2011-02-10 11:22:08.743: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2af9(11001) mgr_view_msg 2011-02-10 11:22:08.744: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb6d02a58 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.744: (debug) [T0x971fdf0 CMGR ]: req_id 0 Start working on message @ 2 : mgr_view_msg 2011-02-10 11:22:08.744: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb6d02a58 count 1 app_data 0xb6d02a58 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source (nil) 2011-02-10 11:22:08.744: (debug) [T0x971fdf0 CMGR ]: req_id 0 Finished working on message 2 2011-02-10 11:22:08.744: (debug) app_data 0xb6d01e68 count 1 app_data 0xb6d01e68 group_id 94aaf91c vp count {0 1} node 0 app_key {0 3} consensus 1 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 172 next (nil) update_last_key setting last_key to {0 3} 2011-02-10 11:22:08.744: (debug) before_boot {0 2} 2011-02-10 11:22:08.744: (debug) last message repeated 1 times 2011-02-10 11:22:08.744: (debug) insert_log next_in 1 log_min {0 1} log_max {0 2} a->key {0 3} 2011-02-10 11:22:08.744: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb6d01e68 msg_count(a)=0x1(1) 2011-02-10 11:22:08.744: (debug) replace_app_data_single location target 0x9738320 app_data (nil) count 0 source 0xb6d01e68 app_data 0xb6d01e68 group_id 94aaf91c vp count {0 1} node 0 app_key {0 3} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 172 next (nil) 2011-02-10 11:22:08.744: (debug) lookup_log_index key {0 3} returns 2 2011-02-10 11:22:08.744: (debug) lookup_log returns 0x9717728 lookup_log_index key {0 4} returns -1 2011-02-10 11:22:08.744: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb6d02dd0 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:08.744: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb6d02dd0 count 1 app_data 0xb6d02dd0 group_id 94aaf91c vp count {0 1} node 0 app_key {0 1} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_set_group length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.744: (debug) deliver message status 0 app_data 0xb6d01e68 count 1 app_data 0xb6d01e68 group_id 94aaf91c vp count {0 1} node 0 app_key {0 3} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 172 next (nil) 2011-02-10 11:22:08.744: (debug) [T0x9706008 chass@message-broker.c:155]: message_broker(): putting site in cluster manager queue 2011-02-10 11:22:08.745: (debug) executed message {0 3} 2011-02-10 11:22:08.745: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2711(10001) mgr_create_site 2011-02-10 11:22:08.745: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb6d01e68 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.745: (message) [T0x971fdf0 CMGR ]: req_id 1 Start working on message @ 3 : mgr_create_site 2011-02-10 11:22:08.745: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb6d01e68 count 1 app_data 0xb6d01e68 group_id 94aaf91c vp count {0 1} node 0 app_key {0 3} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 172 next (nil) source (nil) 2011-02-10 11:22:08.745: (debug) [T0x971fdf0 CMGR @cluster-manager.c:3955]: Setting site config as vpnum vp_to_u_long_long(site->siteversion)=0x3(3) 2011-02-10 11:22:08.745: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.745: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:45]: Creating opstatus desiredplen=0x0(0) num_hosts=0x1(1) 2011-02-10 11:22:08.745: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:08.745: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:104]: Operation not forced 2011-02-10 11:22:08.745: (debug) vp count {0 1} node 0 node 0 2011-02-10 11:22:08.745: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:08.745: (debug) set_max_version {0 3} 2011-02-10 11:22:08.745: (debug) 2011-02-10 11:22:08.745: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.006411 2011-02-10 11:22:08.746: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0x9716f20 2011-02-10 11:22:08.746: (debug) [T0x971fdf0 CMGR @cluster-manager.c:3902]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0x3(3) op_proc_status_copy->host=`192.168.1.5' 2011-02-10 11:22:08.746: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0x9718958 2011-02-10 11:22:08.746: (message) [T0x971fdf0 CMGR ]: req_id 1 Finished working on message 3 2011-02-10 11:22:08.842: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x97188f0 2011-02-10 11:22:08.842: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.842: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.842: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x97188f0 msg_count(out_msg)=0x1(1) 2011-02-10 11:22:08.842: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0x9718800 msg_count(a)=0x1(1) 2011-02-10 11:22:08.843: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x97188f0 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.843: (debug) vpfsm_process_message executed_key {0 3} last_key {0 3} 2011-02-10 11:22:08.843: (debug) incoming message app_data 0x9718800 count 1 app_data 0x9718800 group_id 94aaf91c vp count {0 2} node 0 app_key {0 4} consensus 2 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 204 next (nil) 2011-02-10 11:22:08.843: (debug) app_data 0x9718800 count 1 app_data 0x9718800 group_id 94aaf91c vp count {0 2} node 0 app_key {0 4} consensus 2 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 204 next (nil) update_last_key setting last_key to {0 4} 2011-02-10 11:22:08.843: (debug) before_boot {0 2} 2011-02-10 11:22:08.843: (debug) last message repeated 1 times 2011-02-10 11:22:08.843: (debug) insert_log next_in 2 log_min {0 1} log_max {0 3} a->key {0 4} 2011-02-10 11:22:08.843: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0x9718800 msg_count(a)=0x1(1) 2011-02-10 11:22:08.843: (debug) replace_app_data_single location target 0x9738324 app_data (nil) count 0 source 0x9718800 app_data 0x9718800 group_id 94aaf91c vp count {0 2} node 0 app_key {0 4} consensus 2 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 204 next (nil) 2011-02-10 11:22:08.843: (debug) lookup_log_index key {0 4} returns 3 2011-02-10 11:22:08.843: (debug) lookup_log returns 0x9718968 lookup_log_index key {0 5} returns -1 2011-02-10 11:22:08.843: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9716e00 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:08.843: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9716e00 count 1 app_data 0x9716e00 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.843: (debug) deliver message status 0 app_data 0x9718800 count 1 app_data 0x9718800 group_id 94aaf91c vp count {0 2} node 0 app_key {0 4} consensus 2 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 204 next (nil) 2011-02-10 11:22:08.844: (debug) [T0x9706008 chass@message-broker.c:290]: message_broker(): putting agent info in cluster manager queue 2011-02-10 11:22:08.844: (debug) executed message {0 4} 2011-02-10 11:22:08.844: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0x9718800 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.844: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2ee0(12000) mgr_agent_info 2011-02-10 11:22:08.844: (debug) replace_app_data_single location target 0xbff57504 app_data 0x9718800 count 1 app_data 0x9718800 group_id 94aaf91c vp count {0 2} node 0 app_key {0 4} consensus 2 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 204 next (nil) source (nil) 2011-02-10 11:22:08.844: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.844: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:08.844: (debug) vp count {0 2} node 0 node 0 2011-02-10 11:22:08.844: (debug) [T0x971fdf0 CMGR ]: req_id 0 Start working on message @ 4 : mgr_agent_info 2011-02-10 11:22:08.844: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4837]: Got a agent_info struct from ai->hostname=`billy-laptop' 2011-02-10 11:22:08.844: (debug) [T0x971fdf0 CMGR ]: req_id 0 Finished working on message 4 2011-02-10 11:22:08.844: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:08.844: (debug) 2011-02-10 11:22:08.844: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002363 2011-02-10 11:22:08.844: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9718a38 2011-02-10 11:22:08.845: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.845: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.845: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x9718a38 msg_count(out_msg)=0x1(1) 2011-02-10 11:22:08.845: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0x97174d8 msg_count(a)=0x1(1) 2011-02-10 11:22:08.845: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x9718a38 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.845: (debug) vpfsm_process_message executed_key {0 4} last_key {0 4} 2011-02-10 11:22:08.845: (debug) incoming message app_data 0x97174d8 count 1 app_data 0x97174d8 group_id 94aaf91c vp count {0 3} node 0 app_key {0 5} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:08.845: (debug) app_data 0x97174d8 count 1 app_data 0x97174d8 group_id 94aaf91c vp count {0 3} node 0 app_key {0 5} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 196 next (nil) update_last_key setting last_key to {0 5} 2011-02-10 11:22:08.845: (debug) before_boot {0 2} 2011-02-10 11:22:08.845: (debug) last message repeated 1 times 2011-02-10 11:22:08.845: (debug) insert_log next_in 3 log_min {0 1} log_max {0 4} a->key {0 5} 2011-02-10 11:22:08.845: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0x97174d8 msg_count(a)=0x1(1) 2011-02-10 11:22:08.845: (debug) replace_app_data_single location target 0x9738328 app_data (nil) count 0 source 0x97174d8 app_data 0x97174d8 group_id 94aaf91c vp count {0 3} node 0 app_key {0 5} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:08.845: (debug) lookup_log_index key {0 5} returns 4 2011-02-10 11:22:08.846: (debug) lookup_log returns 0x9719118 lookup_log_index key {0 6} returns -1 2011-02-10 11:22:08.846: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9716e00 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:08.846: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9716e00 count 1 app_data 0x9716e00 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:08.846: (debug) deliver message status 0 app_data 0x97174d8 count 1 app_data 0x97174d8 group_id 94aaf91c vp count {0 3} node 0 app_key {0 5} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:08.846: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:22:08.846: (debug) executed message {0 5} 2011-02-10 11:22:08.846: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0x97174d8 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.846: (debug) replace_app_data_single location target 0xbff57504 app_data 0x97174d8 count 1 app_data 0x97174d8 group_id 94aaf91c vp count {0 3} node 0 app_key {0 5} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) source (nil) 2011-02-10 11:22:08.846: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:22:08.846: (message) [T0x971fdf0 CMGR ]: req_id 1 Start working on message @ 5 : mgr_process_operationstatus 2011-02-10 11:22:08.846: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:08.846: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:22:08.847: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:08.847: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0xffffffff(-1) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0x3(3) 2011-02-10 11:22:08.847: (debug) vp count {0 3} node 0 node 0 2011-02-10 11:22:08.847: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 3} 2011-02-10 11:22:08.847: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:08.847: (debug) 2011-02-10 11:22:08.847: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_site desiredconfigversion={0 3} Id Host Status DepVer RunVer Code Message -1 192.168.1.5 finished {0 3} {0 3} 0 `Site created successfully' 2011-02-10 11:22:08.847: (message) [T0x971fdf0 CMGR ]: req_id 1 Operation finished for configversion 3 2011-02-10 11:22:08.847: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4674]: Trying to return success to client 2011-02-10 11:22:08.847: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002333 2011-02-10 11:22:08.847: (debug) [T0x971fdf0 CMGR @cluster-manager.c:358]: command_queue_push_success_simple cliaddr=127.0.0.1:43662 req_id 1 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 01 00 00 00 } 2011-02-10 11:22:08.847: (debug) [T0x971fdf0 CMGR @cluster-manager.c:366]: Push simple success reply to command queue 2011-02-10 11:22:08.847: (message) [T0x971fdf0 CMGR ]: req_id 1 Finished working on message 5 2011-02-10 11:22:09.170: (debug) [T0x9706008 chass@message-broker.c:643]: Got reply object from command_queue, destined for &reply_->cliaddr=127.0.0.1:43662 req_id 1 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 01 00 00 00 } 2011-02-10 11:22:09.170: (debug) [T0x9706008 chass@message-broker.c:646]: Inserting into hash table 2011-02-10 11:22:09.170: (debug) [T0x9706008 chass@message-broker.c:666]: qcon=0xb6d02278 qcon->client->fd=0xe(14) reply_=0xb6d02ec8 reply_={ &tp->cliaddr=127.0.0.1:43662 req_id 1 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 01 00 00 00 } reply={{ Command result }{ Site created successfully }}} 2011-02-10 11:22:09.170: (debug) [T0x9706008 chass@message-broker.c:682]: Before calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT 2011-02-10 11:22:09.170: (message) [T0x9706008 chass]: Returning success to client: 1 row(s): { { Site created successfully } } 2011-02-10 11:22:09.170: (debug) [T0x9706008 chass@message-broker.c:689]: Calling network_mysqld_con_handle 2011-02-10 11:22:09.171: (debug) [T0x9706008 chass@message-broker.c:705]: After calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT qcon->state=10 2011-02-10 11:22:33.030: (message) [T0x9706008 chass]: Received command : add package --basedir=/usr/local/mysql_6_3_39 6_3 2011-02-10 11:22:33.030: (debug) [T0x9706008 chass@manager-commands.c:2404]: escaped_cmdline=`add package --basedir=/usr/local/mysql_6_3_39 6_3' 2011-02-10 11:22:33.030: (debug) [T0x9706008 chass@manager-commands.c:2517]: Adding option to commands option list : basedir 2011-02-10 11:22:33.030: (debug) [T0x9706008 chass@manager-commands.c:2523]: Adding operand to commands operand list : 6_3 2011-02-10 11:22:33.030: (debug) [T0x9706008 chass@manager-commands.c:2048]: handle_add_package() 2011-02-10 11:22:33.031: (debug) [T0x9706008 chass@manager-commands.c:2059]: basedir=`/usr/local/mysql_6_3_39' 2011-02-10 11:22:33.031: (debug) [T0x9706008 chass@manager-commands.c:2071]: handle_add_package() : packagename = 6_3 2011-02-10 11:22:33.031: (message) [T0x9706008 chass]: Handling request id 2 2011-02-10 11:22:33.031: (debug) [T0x9706008 chass@manager-commands.c:2110]: INIT_CLIENT_ADDRESS &msg->client_address=127.0.0.1:43662 req_id 2 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 02 00 00 00 } 2011-02-10 11:22:33.031: (debug) [T0x9706008 chass@message-broker.c:181]: message_broker(): putting site package in cluster manager queue 2011-02-10 11:22:33.031: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0xb(11) api_create_package 2011-02-10 11:22:33.031: (message) [T0x971fdf0 CMGR ]: req_id 2 Start working on message @ 0 : api_create_package 2011-02-10 11:22:33.031: (debug) [T0x971fdf0 CMGR @cluster-manager.c:894]: handle_api_sitepackage 2011-02-10 11:22:33.031: (debug) [T0x971fdf0 CMGR @cluster-manager.c:899]: Verifying that local site exists 2011-02-10 11:22:33.031: (debug) [T0x971fdf0 CMGR @cluster-manager.c:991]: Package pkg->packagename=`6_3' not defined in site. Adding information 2011-02-10 11:22:33.031: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0x9718f00 2011-02-10 11:22:33.031: (message) [T0x971fdf0 CMGR ]: req_id 2 Finished working on message 0 2011-02-10 11:22:33.066: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0xb6d02b90 2011-02-10 11:22:33.066: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.066: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.066: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0xb6d02b90 msg_count(out_msg)=0x1(1) 2011-02-10 11:22:33.066: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0x9718a20 msg_count(a)=0x1(1) 2011-02-10 11:22:33.066: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0xb6d02b90 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.066: (debug) vpfsm_process_message executed_key {0 5} last_key {0 5} 2011-02-10 11:22:33.066: (debug) incoming message app_data 0x9718a20 count 1 app_data 0x9718a20 group_id 94aaf91c vp count {0 4} node 0 app_key {0 6} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 184 next (nil) 2011-02-10 11:22:33.067: (debug) app_data 0x9718a20 count 1 app_data 0x9718a20 group_id 94aaf91c vp count {0 4} node 0 app_key {0 6} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 184 next (nil) update_last_key setting last_key to {0 6} 2011-02-10 11:22:33.067: (debug) before_boot {0 2} 2011-02-10 11:22:33.067: (debug) last message repeated 1 times 2011-02-10 11:22:33.067: (debug) insert_log next_in 4 log_min {0 1} log_max {0 5} a->key {0 6} 2011-02-10 11:22:33.067: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0x9718a20 msg_count(a)=0x1(1) 2011-02-10 11:22:33.067: (debug) replace_app_data_single location target 0x973832c app_data (nil) count 0 source 0x9718a20 app_data 0x9718a20 group_id 94aaf91c vp count {0 4} node 0 app_key {0 6} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 184 next (nil) 2011-02-10 11:22:33.067: (debug) lookup_log_index key {0 6} returns 5 2011-02-10 11:22:33.067: (debug) lookup_log returns 0x97195a8 lookup_log_index key {0 7} returns -1 2011-02-10 11:22:33.067: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9717528 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:33.068: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9717528 count 1 app_data 0x9717528 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:33.068: (debug) deliver message status 0 app_data 0x9718a20 count 1 app_data 0x9718a20 group_id 94aaf91c vp count {0 4} node 0 app_key {0 6} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 184 next (nil) 2011-02-10 11:22:33.068: (debug) [T0x9706008 chass@message-broker.c:181]: message_broker(): putting site package in cluster manager queue 2011-02-10 11:22:33.068: (debug) executed message {0 6} 2011-02-10 11:22:33.068: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0x9718a20 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.068: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x271b(10011) mgr_create_package 2011-02-10 11:22:33.068: (debug) replace_app_data_single location target 0xbff57504 app_data 0x9718a20 count 1 app_data 0x9718a20 group_id 94aaf91c vp count {0 4} node 0 app_key {0 6} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 184 next (nil) source (nil) 2011-02-10 11:22:33.068: (message) [T0x971fdf0 CMGR ]: req_id 2 Start working on message @ 6 : mgr_create_package 2011-02-10 11:22:33.068: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4038]: Verifying that local site exists 2011-02-10 11:22:33.068: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.068: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:45]: Creating opstatus desiredplen=0x0(0) num_hosts=0x1(1) 2011-02-10 11:22:33.068: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:33.068: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:104]: Operation not forced 2011-02-10 11:22:33.068: (debug) vp count {0 4} node 0 node 0 2011-02-10 11:22:33.068: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:33.068: (debug) 2011-02-10 11:22:33.068: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002466 2011-02-10 11:22:33.068: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1846]: trying ip addresses of myent->h_name=`billy-laptop' 2011-02-10 11:22:33.068: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1865]: checking ip g=`127.0.1.1' name_to_check=`192.168.1.5' myent->h_name=`billy-laptop' 2011-02-10 11:22:33.069: (debug) [T0x971fdf0 CMGR @package-handler.c:63]: Check package for process 'mysqld' on path '/usr/local/mysql_6_3_39' 2011-02-10 11:22:33.210: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4079]: msg=`Package added successfully' 2011-02-10 11:22:33.210: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 6} 2011-02-10 11:22:33.210: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_package desiredconfigversion={0 6} Id Host Status DepVer RunVer Code Message -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:22:33.210: (debug) [T0x971fdf0 CMGR @cluster-manager.c:3902]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0x6(6) op_proc_status_copy->host=`192.168.1.5' 2011-02-10 11:22:33.210: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0xb6d03410 2011-02-10 11:22:33.210: (message) [T0x971fdf0 CMGR ]: req_id 2 Finished working on message 6 2011-02-10 11:22:33.271: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0xb6d03458 2011-02-10 11:22:33.271: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.271: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.271: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0xb6d03458 msg_count(out_msg)=0x1(1) 2011-02-10 11:22:33.271: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0x9717f00 msg_count(a)=0x1(1) 2011-02-10 11:22:33.272: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0xb6d03458 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.272: (debug) vpfsm_process_message executed_key {0 6} last_key {0 6} 2011-02-10 11:22:33.272: (debug) incoming message app_data 0x9717f00 count 1 app_data 0x9717f00 group_id 94aaf91c vp count {0 5} node 0 app_key {0 7} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:33.272: (debug) app_data 0x9717f00 count 1 app_data 0x9717f00 group_id 94aaf91c vp count {0 5} node 0 app_key {0 7} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 196 next (nil) update_last_key setting last_key to {0 7} 2011-02-10 11:22:33.272: (debug) before_boot {0 2} 2011-02-10 11:22:33.272: (debug) last message repeated 1 times 2011-02-10 11:22:33.272: (debug) insert_log next_in 5 log_min {0 1} log_max {0 6} a->key {0 7} 2011-02-10 11:22:33.272: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0x9717f00 msg_count(a)=0x1(1) 2011-02-10 11:22:33.272: (debug) replace_app_data_single location target 0x9738330 app_data (nil) count 0 source 0x9717f00 app_data 0x9717f00 group_id 94aaf91c vp count {0 5} node 0 app_key {0 7} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:33.272: (debug) lookup_log_index key {0 7} returns 6 2011-02-10 11:22:33.272: (debug) lookup_log returns 0x97196c0 lookup_log_index key {0 8} returns -1 2011-02-10 11:22:33.272: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9716e00 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:33.273: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9716e00 count 1 app_data 0x9716e00 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:33.273: (debug) deliver message status 0 app_data 0x9717f00 count 1 app_data 0x9717f00 group_id 94aaf91c vp count {0 5} node 0 app_key {0 7} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:33.273: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:22:33.273: (debug) executed message {0 7} 2011-02-10 11:22:33.273: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0x9717f00 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.273: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:22:33.273: (message) [T0x971fdf0 CMGR ]: req_id 2 Start working on message @ 7 : mgr_process_operationstatus 2011-02-10 11:22:33.273: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:22:33.273: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0xffffffff(-1) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0x6(6) 2011-02-10 11:22:33.273: (debug) replace_app_data_single location target 0xbff57504 app_data 0x9717f00 count 1 app_data 0x9717f00 group_id 94aaf91c vp count {0 5} node 0 app_key {0 7} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) source (nil) 2011-02-10 11:22:33.273: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 6} 2011-02-10 11:22:33.273: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:33.274: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:33.274: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_package desiredconfigversion={0 6} Id Host Status DepVer RunVer Code Message -1 192.168.1.5 finished {0 6} {0 6} 0 `Package added successfully' 2011-02-10 11:22:33.274: (message) [T0x971fdf0 CMGR ]: req_id 2 Operation finished for configversion 6 2011-02-10 11:22:33.274: (debug) vp count {0 5} node 0 node 0 2011-02-10 11:22:33.274: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4674]: Trying to return success to client 2011-02-10 11:22:33.274: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:33.274: (debug) [T0x971fdf0 CMGR @cluster-manager.c:358]: command_queue_push_success_simple cliaddr=127.0.0.1:43662 req_id 2 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 02 00 00 00 } 2011-02-10 11:22:33.274: (debug) 2011-02-10 11:22:33.274: (debug) [T0x971fdf0 CMGR @cluster-manager.c:366]: Push simple success reply to command queue 2011-02-10 11:22:33.274: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002949 2011-02-10 11:22:33.274: (message) [T0x971fdf0 CMGR ]: req_id 2 Finished working on message 7 2011-02-10 11:22:34.238: (debug) [T0x9706008 chass@message-broker.c:643]: Got reply object from command_queue, destined for &reply_->cliaddr=127.0.0.1:43662 req_id 2 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 02 00 00 00 } 2011-02-10 11:22:34.238: (debug) [T0x9706008 chass@message-broker.c:658]: Updating last replied req_id hw->req_id=0x1(1) reply_->cliaddr.req_id=0x2(2) 2011-02-10 11:22:34.238: (debug) [T0x9706008 chass@message-broker.c:666]: qcon=0xb6d02278 qcon->client->fd=0xe(14) reply_=0xb6d02b00 reply_={ &tp->cliaddr=127.0.0.1:43662 req_id 2 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 02 00 00 00 } reply={{ Command result }{ Package added successfully }}} 2011-02-10 11:22:34.238: (debug) [T0x9706008 chass@message-broker.c:682]: Before calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT 2011-02-10 11:22:34.238: (message) [T0x9706008 chass]: Returning success to client: 1 row(s): { { Package added successfully } } 2011-02-10 11:22:34.238: (debug) [T0x9706008 chass@message-broker.c:689]: Calling network_mysqld_con_handle 2011-02-10 11:22:34.238: (debug) [T0x9706008 chass@message-broker.c:705]: After calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT qcon->state=10 2011-02-10 11:22:45.470: (message) [T0x9706008 chass]: Received command : add package --basedir=/usr/local/mysql_7_1_9a 7_1 2011-02-10 11:22:45.470: (debug) [T0x9706008 chass@manager-commands.c:2404]: escaped_cmdline=`add package --basedir=/usr/local/mysql_7_1_9a 7_1' 2011-02-10 11:22:45.470: (debug) [T0x9706008 chass@manager-commands.c:2517]: Adding option to commands option list : basedir 2011-02-10 11:22:45.470: (debug) [T0x9706008 chass@manager-commands.c:2523]: Adding operand to commands operand list : 7_1 2011-02-10 11:22:45.470: (debug) [T0x9706008 chass@manager-commands.c:2048]: handle_add_package() 2011-02-10 11:22:45.470: (debug) [T0x9706008 chass@manager-commands.c:2059]: basedir=`/usr/local/mysql_7_1_9a' 2011-02-10 11:22:45.471: (debug) [T0x9706008 chass@manager-commands.c:2071]: handle_add_package() : packagename = 7_1 2011-02-10 11:22:45.471: (message) [T0x9706008 chass]: Handling request id 3 2011-02-10 11:22:45.471: (debug) [T0x9706008 chass@manager-commands.c:2110]: INIT_CLIENT_ADDRESS &msg->client_address=127.0.0.1:43662 req_id 3 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 03 00 00 00 } 2011-02-10 11:22:45.471: (debug) [T0x9706008 chass@message-broker.c:181]: message_broker(): putting site package in cluster manager queue 2011-02-10 11:22:45.471: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0xb(11) api_create_package 2011-02-10 11:22:45.471: (message) [T0x971fdf0 CMGR ]: req_id 3 Start working on message @ 0 : api_create_package 2011-02-10 11:22:45.471: (debug) [T0x971fdf0 CMGR @cluster-manager.c:894]: handle_api_sitepackage 2011-02-10 11:22:45.471: (debug) [T0x971fdf0 CMGR @cluster-manager.c:899]: Verifying that local site exists 2011-02-10 11:22:45.471: (debug) [T0x971fdf0 CMGR @cluster-manager.c:991]: Package pkg->packagename=`7_1' not defined in site. Adding information 2011-02-10 11:22:45.471: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0x9716220 2011-02-10 11:22:45.471: (message) [T0x971fdf0 CMGR ]: req_id 3 Finished working on message 0 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0xb6d02ba0 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0xb6d02ba0 msg_count(out_msg)=0x1(1) 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0x9715ff0 msg_count(a)=0x1(1) 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0xb6d02ba0 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.534: (debug) vpfsm_process_message executed_key {0 7} last_key {0 7} 2011-02-10 11:22:45.534: (debug) incoming message app_data 0x9715ff0 count 1 app_data 0x9715ff0 group_id 94aaf91c vp count {0 6} node 0 app_key {0 8} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 184 next (nil) 2011-02-10 11:22:45.534: (debug) app_data 0x9715ff0 count 1 app_data 0x9715ff0 group_id 94aaf91c vp count {0 6} node 0 app_key {0 8} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 184 next (nil) update_last_key setting last_key to {0 8} 2011-02-10 11:22:45.534: (debug) before_boot {0 2} 2011-02-10 11:22:45.534: (debug) last message repeated 1 times 2011-02-10 11:22:45.534: (debug) insert_log next_in 6 log_min {0 1} log_max {0 7} a->key {0 8} 2011-02-10 11:22:45.534: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0x9715ff0 msg_count(a)=0x1(1) 2011-02-10 11:22:45.534: (debug) replace_app_data_single location target 0x9738334 app_data (nil) count 0 source 0x9715ff0 app_data 0x9715ff0 group_id 94aaf91c vp count {0 6} node 0 app_key {0 8} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 184 next (nil) 2011-02-10 11:22:45.535: (debug) lookup_log_index key {0 8} returns 7 2011-02-10 11:22:45.535: (debug) lookup_log returns 0x9718e18 lookup_log_index key {0 9} returns -1 2011-02-10 11:22:45.535: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9716e00 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:45.535: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9716e00 count 1 app_data 0x9716e00 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:45.535: (debug) deliver message status 0 app_data 0x9715ff0 count 1 app_data 0x9715ff0 group_id 94aaf91c vp count {0 6} node 0 app_key {0 8} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 184 next (nil) 2011-02-10 11:22:45.535: (debug) [T0x9706008 chass@message-broker.c:181]: message_broker(): putting site package in cluster manager queue 2011-02-10 11:22:45.535: (debug) executed message {0 8} 2011-02-10 11:22:45.535: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0x9715ff0 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.535: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x271b(10011) mgr_create_package 2011-02-10 11:22:45.535: (debug) replace_app_data_single location target 0xbff57504 app_data 0x9715ff0 count 1 app_data 0x9715ff0 group_id 94aaf91c vp count {0 6} node 0 app_key {0 8} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 184 next (nil) source (nil) 2011-02-10 11:22:45.535: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.535: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:45.535: (debug) vp count {0 6} node 0 node 0 2011-02-10 11:22:45.535: (message) [T0x971fdf0 CMGR ]: req_id 3 Start working on message @ 8 : mgr_create_package 2011-02-10 11:22:45.535: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4038]: Verifying that local site exists 2011-02-10 11:22:45.536: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:45.536: (debug) 2011-02-10 11:22:45.536: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:45]: Creating opstatus desiredplen=0x0(0) num_hosts=0x1(1) 2011-02-10 11:22:45.536: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:104]: Operation not forced 2011-02-10 11:22:45.536: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.001839 2011-02-10 11:22:45.536: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1846]: trying ip addresses of myent->h_name=`billy-laptop' 2011-02-10 11:22:45.536: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1865]: checking ip g=`127.0.1.1' name_to_check=`192.168.1.5' myent->h_name=`billy-laptop' 2011-02-10 11:22:45.536: (debug) [T0x971fdf0 CMGR @package-handler.c:63]: Check package for process 'mysqld' on path '/usr/local/mysql_7_1_9a' 2011-02-10 11:22:45.769: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4079]: msg=`Package added successfully' 2011-02-10 11:22:45.769: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 8} 2011-02-10 11:22:45.769: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_package desiredconfigversion={0 8} Id Host Status DepVer RunVer Code Message -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:22:45.769: (debug) [T0x971fdf0 CMGR @cluster-manager.c:3902]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0x8(8) op_proc_status_copy->host=`192.168.1.5' 2011-02-10 11:22:45.769: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0x9718de0 2011-02-10 11:22:45.769: (message) [T0x971fdf0 CMGR ]: req_id 3 Finished working on message 8 2011-02-10 11:22:45.839: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x97188b8 2011-02-10 11:22:45.839: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.839: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.839: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x97188b8 msg_count(out_msg)=0x1(1) 2011-02-10 11:22:45.839: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb6d02b90 msg_count(a)=0x1(1) 2011-02-10 11:22:45.840: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x97188b8 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.840: (debug) vpfsm_process_message executed_key {0 8} last_key {0 8} 2011-02-10 11:22:45.840: (debug) incoming message app_data 0xb6d02b90 count 1 app_data 0xb6d02b90 group_id 94aaf91c vp count {0 7} node 0 app_key {0 9} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:45.840: (debug) app_data 0xb6d02b90 count 1 app_data 0xb6d02b90 group_id 94aaf91c vp count {0 7} node 0 app_key {0 9} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 196 next (nil) update_last_key setting last_key to {0 9} 2011-02-10 11:22:45.840: (debug) before_boot {0 2} 2011-02-10 11:22:45.840: (debug) last message repeated 1 times 2011-02-10 11:22:45.840: (debug) insert_log next_in 7 log_min {0 1} log_max {0 8} a->key {0 9} 2011-02-10 11:22:45.840: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb6d02b90 msg_count(a)=0x1(1) 2011-02-10 11:22:45.840: (debug) replace_app_data_single location target 0x9738338 app_data (nil) count 0 source 0xb6d02b90 app_data 0xb6d02b90 group_id 94aaf91c vp count {0 7} node 0 app_key {0 9} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:45.840: (debug) lookup_log_index key {0 9} returns 8 2011-02-10 11:22:45.840: (debug) lookup_log returns 0xb6d02e70 lookup_log_index key {0 10} returns -1 2011-02-10 11:22:45.840: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0x9716e00 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:22:45.841: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0x9716e00 count 1 app_data 0x9716e00 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:22:45.841: (debug) deliver message status 0 app_data 0xb6d02b90 count 1 app_data 0xb6d02b90 group_id 94aaf91c vp count {0 7} node 0 app_key {0 9} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) 2011-02-10 11:22:45.841: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:22:45.841: (debug) executed message {0 9} 2011-02-10 11:22:45.841: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb6d02b90 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.841: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:22:45.841: (message) [T0x971fdf0 CMGR ]: req_id 3 Start working on message @ 9 : mgr_process_operationstatus 2011-02-10 11:22:45.841: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:22:45.841: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0xffffffff(-1) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0x8(8) 2011-02-10 11:22:45.841: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 8} 2011-02-10 11:22:45.841: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_package desiredconfigversion={0 8} Id Host Status DepVer RunVer Code Message -1 192.168.1.5 finished {0 8} {0 8} 0 `Package added successfully' 2011-02-10 11:22:45.841: (message) [T0x971fdf0 CMGR ]: req_id 3 Operation finished for configversion 8 2011-02-10 11:22:45.842: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4674]: Trying to return success to client 2011-02-10 11:22:45.842: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb6d02b90 count 1 app_data 0xb6d02b90 group_id 94aaf91c vp count {0 7} node 0 app_key {0 9} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 196 next (nil) source (nil) 2011-02-10 11:22:45.842: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:22:45.842: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:22:45.842: (debug) vp count {0 7} node 0 node 0 2011-02-10 11:22:45.842: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:22:45.842: (debug) 2011-02-10 11:22:45.842: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002880 2011-02-10 11:22:45.842: (debug) [T0x971fdf0 CMGR @cluster-manager.c:358]: command_queue_push_success_simple cliaddr=127.0.0.1:43662 req_id 3 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 03 00 00 00 } 2011-02-10 11:22:45.842: (debug) [T0x971fdf0 CMGR @cluster-manager.c:366]: Push simple success reply to command queue 2011-02-10 11:22:45.842: (message) [T0x971fdf0 CMGR ]: req_id 3 Finished working on message 9 2011-02-10 11:22:46.271: (debug) [T0x9706008 chass@message-broker.c:643]: Got reply object from command_queue, destined for &reply_->cliaddr=127.0.0.1:43662 req_id 3 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 03 00 00 00 } 2011-02-10 11:22:46.271: (debug) [T0x9706008 chass@message-broker.c:658]: Updating last replied req_id hw->req_id=0x2(2) reply_->cliaddr.req_id=0x3(3) 2011-02-10 11:22:46.271: (debug) [T0x9706008 chass@message-broker.c:666]: qcon=0xb6d02278 qcon->client->fd=0xe(14) reply_=0x9717520 reply_={ &tp->cliaddr=127.0.0.1:43662 req_id 3 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 03 00 00 00 } reply={{ Command result }{ Package added successfully }}} 2011-02-10 11:22:46.271: (debug) [T0x9706008 chass@message-broker.c:682]: Before calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT 2011-02-10 11:22:46.271: (message) [T0x9706008 chass]: Returning success to client: 1 row(s): { { Package added successfully } } 2011-02-10 11:22:46.271: (debug) [T0x9706008 chass@message-broker.c:689]: Calling network_mysqld_con_handle 2011-02-10 11:22:46.271: (debug) [T0x9706008 chass@message-broker.c:705]: After calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT qcon->state=10 2011-02-10 11:23:05.415: (message) [T0x9706008 chass]: Received command : create create cluster --package=6_3 --processhosts=ndb_mgmd@192.168.1.5,ndbd@192.168.1.5,ndbd@192.168.1.5,mysqld@192.168.1.5,mysqld@192.168.1.5 mycluster 2011-02-10 11:23:05.415: (debug) [T0x9706008 chass@manager-commands.c:2331]: get_command_name(): No such command : create create 2011-02-10 11:23:05.415: (debug) [T0x9706008 chass@manager-commands.c:2360]: legal_command(): No such command : create create 2011-02-10 11:23:05.415: (debug) [T0x9706008 chass@manager-commands.c:2331]: get_command_name(): No such command : create create 2011-02-10 11:23:05.415: (message) [T0x9706008 chass]: Returning error to client : 2 Unrecognized command: create create 2011-02-10 11:23:13.402: (message) [T0x9706008 chass]: Received command : create cluster --package=6_3 --processhosts=ndb_mgmd@192.168.1.5,ndbd@192.168.1.5,ndbd@192.168.1.5,mysqld@192.168.1.5,mysqld@192.168.1.5 mycluster 2011-02-10 11:23:13.402: (debug) [T0x9706008 chass@manager-commands.c:2404]: escaped_cmdline=`create cluster --package=6_3 --processhosts=ndb_mgmd@192.168.1.5,ndbd@192.168.1.5,ndbd@192.168.1.5,mysqld@192.168.1.5,mysqld@192.168.1.5 mycluster' 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:2517]: Adding option to commands option list : package 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:2517]: Adding option to commands option list : processhosts 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:2523]: Adding operand to commands operand list : mycluster 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:464]: handle_create_cluster() 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:472]: handle_create_cluster() : clustername = mycluster 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:491]: packagename=`6_3' 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:495]: processhosts=`ndb_mgmd@192.168.1.5,ndbd@192.168.1.5,ndbd@192.168.1.5,mysqld@192.168.1.5,mysqld@192.168.1.5' 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:502]: prochost len = 2 2011-02-10 11:23:13.403: (debug) last message repeated 4 times 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:545]: ../../../plugins/manager/manager-commands.c:545 : Using registered package 6_3 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:553]: Creating cluster config object 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:564]: currentprochost = ndb_mgmd@192.168.1.5 2011-02-10 11:23:13.403: (debug) [T0x9706008 chass@manager-commands.c:577]: proc@hostname = ndb_mgmd @ 192.168.1.5 2011-02-10 11:23:13.403: (warning) [T0x9706008 chass]: No agent_info for agent on 192.168.1.5. Using my own manager-directory value: `/home/billy/mysq/mcm2/manager' 2011-02-10 11:23:13.404: (debug) [T0x9706008 chass@manager-commands.c:598]: creating process prochost[0]=`ndb_mgmd' 2011-02-10 11:23:13.404: (debug) [T0x9706008 chass@manager-api-util.c:749]: Adding procname=`ndb_mgmd' internalid=0x1(1) 2011-02-10 11:23:13.404: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'config.ini' 2011-02-10 11:23:13.404: (debug) [T0x9706008 chass@manager-xml.c:2026]: Initializing xml config definitions from executable /usr/local/mysql_6_3_39/bin/ndb_config --xml --configinfo 2011-02-10 11:23:13.612: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'SYSTEM' should be ignored 2011-02-10 11:23:13.623: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'NDBD DEFAULT' should be ignored 2011-02-10 11:23:13.625: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'MYSQLD DEFAULT' should be ignored 2011-02-10 11:23:13.626: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'NDB_MGMD DEFAULT' should be ignored 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1870]: Copy restart scope list from config template for parameter 'HostName1' 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1888]: Append config var def 'HostName1' to list of valid parameters 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1625]: Config var def: name=HostName1 comment= type=TYPE_STRING checkType=CHECK_NONE defaultval= min= max= mandatory=FALSE restartType=RESTART_ROLLING initial=FALSE supportType=SUPPORTED_YES 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1626]: Restart scope list: 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1607]: all 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1870]: Copy restart scope list from config template for parameter 'HostName2' 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1888]: Append config var def 'HostName2' to list of valid parameters 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1625]: Config var def: name=HostName2 comment= type=TYPE_STRING checkType=CHECK_NONE defaultval= min= max= mandatory=FALSE restartType=RESTART_ROLLING initial=FALSE supportType=SUPPORTED_YES 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1626]: Restart scope list: 2011-02-10 11:23:13.628: (debug) [T0x9706008 chass@manager-xml.c:1607]: all 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'TCP DEFAULT' should be ignored 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Signum' not fully supported 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId1' not fully supported 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId2' not fully supported 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Group' not fully supported 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeIdServer' not fully supported 2011-02-10 11:23:13.629: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SendSignalId' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Checksum' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'ShmKey' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'ShmSize' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'SHM' should be ignored 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Signum' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId1' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId2' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Group' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeIdServer' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SendSignalId' not fully supported 2011-02-10 11:23:13.630: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Checksum' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'ShmKey' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'ShmSize' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'SHM DEFAULT' should be ignored 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId1' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId2' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Group' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeIdServer' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host1SciId0' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host1SciId1' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host2SciId0' not fully supported 2011-02-10 11:23:13.631: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host2SciId1' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SendSignalId' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Checksum' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SendLimit' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SharedBufferSize' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'SCI' should be ignored 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId1' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeId2' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Group' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'NodeIdServer' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host1SciId0' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host1SciId1' not fully supported 2011-02-10 11:23:13.632: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host2SciId0' not fully supported 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Host2SciId1' not fully supported 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SendSignalId' not fully supported 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'Checksum' not fully supported 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SendLimit' not fully supported 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-xml.c:1925]: Config var def 'SharedBufferSize' not fully supported 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-xml.c:1907]: Section def 'SCI DEFAULT' should be ignored 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='ndb_mgmd', key='nodeid', proct1='ndb_mgmd', pid1='1', proct2='', pid2='', val='1', pri=1, readonly=1 2011-02-10 11:23:13.633: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='datadir', proct1='ndb_mgmd', pid1='1', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/1/data', pri=2, readonly=0 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='hostname', proct1='ndb_mgmd', pid1='1', proct2='', pid2='', val='192.168.1.5', pri=3, readonly=1 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-commands.c:564]: currentprochost = ndbd@192.168.1.5 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-commands.c:577]: proc@hostname = ndbd @ 192.168.1.5 2011-02-10 11:23:13.634: (warning) [T0x9706008 chass]: No agent_info for agent on 192.168.1.5. Using my own manager-directory value: `/home/billy/mysq/mcm2/manager' 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-commands.c:598]: creating process prochost[0]=`ndbd' 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-api-util.c:749]: Adding procname=`ndbd' internalid=0x2(2) 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'config.ini' 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='ndbd', key='nodeid', proct1='ndbd', pid1='2', proct2='', pid2='', val='2', pri=4, readonly=1 2011-02-10 11:23:13.634: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='datadir', proct1='ndbd', pid1='2', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/2/data', pri=5, readonly=0 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='hostname', proct1='ndbd', pid1='2', proct2='', pid2='', val='192.168.1.5', pri=6, readonly=1 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-commands.c:564]: currentprochost = ndbd@192.168.1.5 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-commands.c:577]: proc@hostname = ndbd @ 192.168.1.5 2011-02-10 11:23:13.635: (warning) [T0x9706008 chass]: No agent_info for agent on 192.168.1.5. Using my own manager-directory value: `/home/billy/mysq/mcm2/manager' 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-commands.c:598]: creating process prochost[0]=`ndbd' 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-api-util.c:749]: Adding procname=`ndbd' internalid=0x3(3) 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'config.ini' 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='ndbd', key='nodeid', proct1='ndbd', pid1='3', proct2='', pid2='', val='3', pri=7, readonly=1 2011-02-10 11:23:13.635: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='datadir', proct1='ndbd', pid1='3', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/3/data', pri=8, readonly=0 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='hostname', proct1='ndbd', pid1='3', proct2='', pid2='', val='192.168.1.5', pri=9, readonly=1 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-commands.c:564]: currentprochost = mysqld@192.168.1.5 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-commands.c:577]: proc@hostname = mysqld @ 192.168.1.5 2011-02-10 11:23:13.636: (warning) [T0x9706008 chass]: No agent_info for agent on 192.168.1.5. Using my own manager-directory value: `/home/billy/mysq/mcm2/manager' 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-commands.c:598]: creating process prochost[0]=`mysqld' 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-api-util.c:749]: Adding procname=`mysqld' internalid=0x4(4) 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'my.cnf' 2011-02-10 11:23:13.636: (debug) [T0x9706008 chass@manager-xml.c:2006]: Initializing xml config definitions from file /home/billy/mysql/mcm2/var/mysql_configdef.xml 2011-02-10 11:23:13.640: (debug) [T0x9706008 chass@manager-xml.c:1922]: Config var def 'default_time_zone' already exists 2011-02-10 11:23:13.641: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='mysqld', key='ndb_nodeid', proct1='mysqld', pid1='4', proct2='', pid2='', val='4', pri=10, readonly=1 2011-02-10 11:23:13.641: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='datadir', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/data', pri=11, readonly=0 2011-02-10 11:23:13.641: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='tmpdir', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/data/tmp', pri=12, readonly=0 2011-02-10 11:23:13.642: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='ndbcluster', proct1='mysqld', pid1='4', proct2='', pid2='', val='', pri=13, readonly=1 2011-02-10 11:23:13.642: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='log_error', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/data/mysqld.err', pri=14, readonly=0 2011-02-10 11:23:13.642: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='socket', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock', pri=15, readonly=0 2011-02-10 11:23:13.642: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'config.ini' 2011-02-10 11:23:13.642: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='mysqld', key='nodeid', proct1='mysqld', pid1='4', proct2='', pid2='', val='4', pri=16, readonly=1 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='hostname', proct1='mysqld', pid1='4', proct2='', pid2='', val='192.168.1.5', pri=17, readonly=1 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-commands.c:564]: currentprochost = mysqld@192.168.1.5 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-commands.c:577]: proc@hostname = mysqld @ 192.168.1.5 2011-02-10 11:23:13.643: (warning) [T0x9706008 chass]: No agent_info for agent on 192.168.1.5. Using my own manager-directory value: `/home/billy/mysq/mcm2/manager' 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-commands.c:598]: creating process prochost[0]=`mysqld' 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-api-util.c:749]: Adding procname=`mysqld' internalid=0x5(5) 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'my.cnf' 2011-02-10 11:23:13.643: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='mysqld', key='ndb_nodeid', proct1='mysqld', pid1='5', proct2='', pid2='', val='5', pri=18, readonly=1 2011-02-10 11:23:13.644: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='datadir', proct1='mysqld', pid1='5', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/5/data', pri=19, readonly=0 2011-02-10 11:23:13.644: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='tmpdir', proct1='mysqld', pid1='5', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/5/data/tmp', pri=20, readonly=0 2011-02-10 11:23:13.644: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='ndbcluster', proct1='mysqld', pid1='5', proct2='', pid2='', val='', pri=21, readonly=1 2011-02-10 11:23:13.645: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='log_error', proct1='mysqld', pid1='5', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/5/data/mysqld.err', pri=22, readonly=0 2011-02-10 11:23:13.645: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='socket', proct1='mysqld', pid1='5', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/5/mysql5.sock', pri=23, readonly=0 2011-02-10 11:23:13.645: (debug) [T0x9706008 chass@manager-api-util.c:779]: Initial settings for config file 'config.ini' 2011-02-10 11:23:13.645: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='mysqld', key='nodeid', proct1='mysqld', pid1='5', proct2='', pid2='', val='5', pri=24, readonly=1 2011-02-10 11:23:13.645: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='', key='hostname', proct1='mysqld', pid1='5', proct2='', pid2='', val='192.168.1.5', pri=25, readonly=1 2011-02-10 11:23:13.645: (debug) [T0x9706008 chass@manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`ndb_mgmd' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:13.646: (debug) [T0x9706008 chass@manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`ndbd' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:13.646: (debug) last message repeated 1 times 2011-02-10 11:23:13.646: (debug) [T0x9706008 chass@manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`mysqld' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:13.646: (debug) last message repeated 1 times 2011-02-10 11:23:13.646: (debug) [T0x9706008 chass@manager-api-util.c:944]: Updating processes with url->str=`192.168.1.5:1186' 2011-02-10 11:23:13.646: (debug) [T0x9706008 chass@manager-api-util.c:461]: Setting appended: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=26, readonly=1 2011-02-10 11:23:13.646: (message) [T0x9706008 chass]: Handling request id 4 2011-02-10 11:23:13.646: (debug) [T0x9706008 chass@manager-commands.c:632]: INIT_CLIENT_ADDRESS &msg->client_address=127.0.0.1:43662 req_id 4 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 04 00 00 00 } 2011-02-10 11:23:13.646: (debug) [T0x9706008 chass@message-broker.c:128]: message_broker(): putting new config in cluster manager queue 2011-02-10 11:23:13.646: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x15(21) api_create_cluster 2011-02-10 11:23:13.646: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 0 : api_create_cluster 2011-02-10 11:23:13.646: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2160]: Verifying that local site exists 2011-02-10 11:23:13.646: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2186]: Checking existing config 2011-02-10 11:23:13.646: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2970]: Clearing process restart flags for new config 2011-02-10 11:23:13.646: (message) [T0x971fdf0 CMGR ]: Validating received cluster config 2011-02-10 11:23:13.646: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) last message repeated 1 times 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) last message repeated 1 times 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) last message repeated 1 times 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) last message repeated 1 times 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:13.647: (debug) last message repeated 1 times 2011-02-10 11:23:13.647: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1620]: Copy process package from store 2011-02-10 11:23:13.648: (debug) last message repeated 4 times 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:461]: Match: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=31, readonly=1 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`ndb_mgmd' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`ndbd' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:13.648: (debug) last message repeated 1 times 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`mysqld' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:13.648: (debug) last message repeated 1 times 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:944]: Updating processes with url->str=`192.168.1.5:1186' 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:461]: Setting removed: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=31, readonly=1 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @manager-api-util.c:461]: Setting appended: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=26, readonly=1 2011-02-10 11:23:13.648: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0xb6d10868 2011-02-10 11:23:13.648: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 0 2011-02-10 11:23:13.742: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9719ca0 2011-02-10 11:23:13.742: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:13.742: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:13.742: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x9719ca0 msg_count(out_msg)=0x1(1) 2011-02-10 11:23:13.743: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb6d03a40 msg_count(a)=0x1(1) 2011-02-10 11:23:13.743: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x9719ca0 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:13.743: (debug) vpfsm_process_message executed_key {0 9} last_key {0 9} 2011-02-10 11:23:13.743: (debug) incoming message app_data 0xb6d03a40 count 1 app_data 0xb6d03a40 group_id 94aaf91c vp count {0 8} node 0 app_key {0 10} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) 2011-02-10 11:23:13.743: (debug) app_data 0xb6d03a40 count 1 app_data 0xb6d03a40 group_id 94aaf91c vp count {0 8} node 0 app_key {0 10} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) update_last_key setting last_key to {0 10} 2011-02-10 11:23:13.743: (debug) before_boot {0 2} 2011-02-10 11:23:13.743: (debug) last message repeated 1 times 2011-02-10 11:23:13.743: (debug) insert_log next_in 8 log_min {0 1} log_max {0 9} a->key {0 10} 2011-02-10 11:23:13.743: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb6d03a40 msg_count(a)=0x1(1) 2011-02-10 11:23:13.743: (debug) replace_app_data_single location target 0x973833c app_data (nil) count 0 source 0xb6d03a40 app_data 0xb6d03a40 group_id 94aaf91c vp count {0 8} node 0 app_key {0 10} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) 2011-02-10 11:23:13.743: (debug) lookup_log_index key {0 10} returns 9 2011-02-10 11:23:13.743: (debug) lookup_log returns 0xb6d104d0 lookup_log_index key {0 11} returns -1 2011-02-10 11:23:13.744: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb6d02020 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:13.744: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb6d02020 count 1 app_data 0xb6d02020 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:13.744: (debug) deliver message status 0 app_data 0xb6d03a40 count 1 app_data 0xb6d03a40 group_id 94aaf91c vp count {0 8} node 0 app_key {0 10} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) 2011-02-10 11:23:13.744: (debug) [T0x9706008 chass@message-broker.c:128]: message_broker(): putting new config in cluster manager queue 2011-02-10 11:23:13.744: (debug) executed message {0 10} 2011-02-10 11:23:13.744: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb6d03a40 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:13.744: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2725(10021) mgr_create_cluster 2011-02-10 11:23:13.744: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 10 : mgr_create_cluster 2011-02-10 11:23:13.744: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4251]: Verifying that local site exists 2011-02-10 11:23:13.744: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4256]: Setting configversion as vpnum vp_to_u_long_long(config->configversion)=0xa(10) 2011-02-10 11:23:13.744: (message) [T0x971fdf0 CMGR ]: starting reconfig recovery 2011-02-10 11:23:13.745: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb6d03a40 count 1 app_data 0xb6d03a40 group_id 94aaf91c vp count {0 8} node 0 app_key {0 10} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) source (nil) 2011-02-10 11:23:13.745: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:13.745: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:23:13.745: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5008]: No cluster status found in store, creating one from scratch... 2011-02-10 11:23:13.745: (debug) vp count {0 8} node 0 node 0 2011-02-10 11:23:13.745: (debug) [T0x971fdf0 CMGR @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndb_mgmd' 2011-02-10 11:23:13.745: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:23:13.745: (debug) 2011-02-10 11:23:13.745: (debug) [T0x971fdf0 CMGR @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndbd' 2011-02-10 11:23:13.745: (message) [T0x97174c8 STAT ]: Starting status thread 2011-02-10 11:23:13.745: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002952 2011-02-10 11:23:13.745: (debug) [T0x971fdf0 CMGR @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndbd' 2011-02-10 11:23:13.745: (message) [T0x97194f8 RECFG]: wait recovery 2011-02-10 11:23:13.745: (message) [T0x97194f8 RECFG]: Starting reconfigurator thread 2011-02-10 11:23:13.745: (debug) [T0x971fdf0 CMGR @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`mysqld' 2011-02-10 11:23:13.746: (debug) last message repeated 1 times 2011-02-10 11:23:13.746: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2994]: reconfig_process_message 2011-02-10 11:23:13.746: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:13.746: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_clusterstatus 2011-02-10 11:23:13.746: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1775]: new cluster status 2011-02-10 11:23:13.746: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1508]: updating status initially 2011-02-10 11:23:13.746: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2996]: continue_type NO_NEWS 2011-02-10 11:23:13.746: (debug) [T0x97174c8 STAT @manager-status.c:355]: waiting max for new message on status queue SLEEPTIME=0x4c4b40(5000000) 2011-02-10 11:23:13.746: (debug) [T0x97174c8 STAT @manager-status.c:361]: new message 2011-02-10 11:23:13.746: (debug) [T0x97174c8 STAT @manager-status.c:384]: Got new status queue message : opcode_to_string(mm->payload->code)=`mgr_clusterstatus' 2011-02-10 11:23:13.746: (message) [T0x97174c8 STAT ]: req_id 4 status: ignoring message 11008 2011-02-10 11:23:13.746: (debug) [T0x97174c8 STAT @manager-status.c:355]: waiting max for new message on status queue SLEEPTIME=0x4c4b40(5000000) 2011-02-10 11:23:13.747: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4273]: handle_mgr_cluster_config trying to find correct cluster with name config->clustername=`mycluster' 2011-02-10 11:23:13.747: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:45]: Creating opstatus desiredplen=0x5(5) num_hosts=0x1(1) 2011-02-10 11:23:13.747: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:104]: Operation not forced 2011-02-10 11:23:13.748: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2994]: reconfig_process_message 2011-02-10 11:23:13.748: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:13.748: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_operationstatus 2011-02-10 11:23:13.748: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1792]: new operation status 2011-02-10 11:23:13.749: (debug) [T0x971fdf0 CMGR @cluster-manager.c:207]: save_return_address 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1797]: new operationstatus vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:13.749: (debug) [T0x971fdf0 CMGR @cluster-manager.c:211]: client_address=127.0.0.1:43662 req_id 4 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 04 00 00 00 } 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2996]: continue_type NO_NEWS 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2994]: reconfig_process_message 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_create_cluster 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1688]: new config arrived mgr_create_cluster 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1665]: config processlist size is procsize=0x5(5) 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1671]: processwalker->internalid=0x1(1) processwalker->hostaddress=`192.168.1.5' process_desiredstate_to_string(processwalker)=`stopped' 2011-02-10 11:23:13.749: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1671]: processwalker->internalid=0x2(2) processwalker->hostaddress=`192.168.1.5' process_desiredstate_to_string(processwalker)=`stopped' 2011-02-10 11:23:13.750: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1671]: processwalker->internalid=0x3(3) processwalker->hostaddress=`192.168.1.5' process_desiredstate_to_string(processwalker)=`stopped' 2011-02-10 11:23:13.750: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1671]: processwalker->internalid=0x4(4) processwalker->hostaddress=`192.168.1.5' process_desiredstate_to_string(processwalker)=`stopped' 2011-02-10 11:23:13.750: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1671]: processwalker->internalid=0x5(5) processwalker->hostaddress=`192.168.1.5' process_desiredstate_to_string(processwalker)=`stopped' 2011-02-10 11:23:13.750: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2996]: continue_type NEW_CONFIG 2011-02-10 11:23:13.750: (debug) [T0x97174c8 STAT @manager-status.c:361]: new message 2011-02-10 11:23:13.750: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:13.750: (debug) [T0x97174c8 STAT @manager-status.c:384]: Got new status queue message : opcode_to_string(mm->payload->code)=`mgr_create_cluster' 2011-02-10 11:23:13.750: (debug) [T0x97174c8 STAT @manager-status.c:399]: new config 2011-02-10 11:23:13.750: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 executing {0 0} {0 0} 0 `' 2 192.168.1.5 executing {0 0} {0 0} 0 `' 3 192.168.1.5 executing {0 0} {0 0} 0 `' 4 192.168.1.5 executing {0 0} {0 0} 0 `' 5 192.168.1.5 executing {0 0} {0 0} 0 `' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:13.750: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 10 2011-02-10 11:23:13.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndb_mgmd' proc->internalid=0x1(1) should be stopped, no status query 2011-02-10 11:23:13.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndbd' proc->internalid=0x2(2) should be stopped, no status query 2011-02-10 11:23:13.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndbd' proc->internalid=0x3(3) should be stopped, no status query 2011-02-10 11:23:13.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`mysqld' proc->internalid=0x4(4) should be stopped, no status query 2011-02-10 11:23:13.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`mysqld' proc->internalid=0x5(5) should be stopped, no status query 2011-02-10 11:23:13.751: (debug) [T0x97174c8 STAT @manager-status.c:355]: waiting max for new message on status queue SLEEPTIME=0x4c4b40(5000000) 2011-02-10 11:23:13.845: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:3050]: Executing reconfiguration of popped messages in main loop 2011-02-10 11:23:13.845: (message) [T0x97194f8 RECFG]: req_id 4 Starting the reconfigurator on config 10 2011-02-10 11:23:14.848: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1953]: Processid process->processid=0x4(4) is still not on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) vp_to_u_long_long(process->runningconfigversion)=0x0(0) 2011-02-10 11:23:14.848: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2777]: ctx->curr_startseq=0x3(3) is not done for op_proc_status->processid=0x4(4) 2011-02-10 11:23:14.848: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2597]: my process processwalker->internalid=0x4(4) operationstatus_to_string(op_proc_status->operationstatus)=`executing' 2011-02-10 11:23:14.848: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1043]: Start writing config file for process 'mysqld' 2011-02-10 11:23:14.848: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=27, readonly=1 2011-02-10 11:23:14.849: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=28, readonly=1 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1156]: Done writing config file for process 'mysqld' 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2613]: config written successfully for processwalker->processname=`mysqld' processwalker->internalid=0x4(4) 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-process-manager.c:440]: pidfile does not exist, process not started process->internalid=4 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Match: sec='', key='datadir', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/data', pri=31, readonly=0 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2237]: inserting process into proctable proc_info->internalid=0x4(4) proc_info->os_pid=0xffffffff(-1) 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2238]: insert proc_info 0x9743a08 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2517]: Process being stopped proc_info->processname=`mysqld' proc_info->internalid=0x4(4) 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-process-manager.c:756]: Process is NOT running: proc_info->internalid=4 proc_info->processname=`mysqld' proc_info->os_pid=-1 proc_info->exitstatus=0 2011-02-10 11:23:14.852: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2481]: Update operation status vp_to_u_long_long(op_proc_status->runningconfigversion)=0x0(0) 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:215]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0xa(10) op_proc_status_copy->processid=0x4(4) operationstatus_to_string(op_proc_status_copy->operationstatus)=`finished' op_proc_status_copy->message=`process sucessfully stopped' ctx->current_operation_status->msg->force=0x0(0) 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2556]: Process processwalker->processname=`mysqld' processwalker->internalid=0x4(4) is already stopped, there is nothing to do 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1953]: Processid process->processid=0x5(5) is still not on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) vp_to_u_long_long(process->runningconfigversion)=0x0(0) 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2777]: ctx->curr_startseq=0x3(3) is not done for op_proc_status->processid=0x5(5) 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2597]: my process processwalker->internalid=0x5(5) operationstatus_to_string(op_proc_status->operationstatus)=`executing' 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1043]: Start writing config file for process 'mysqld' 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=31, readonly=1 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=32, readonly=1 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=31, readonly=1 2011-02-10 11:23:14.853: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=33, readonly=1 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1156]: Done writing config file for process 'mysqld' 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2613]: config written successfully for processwalker->processname=`mysqld' processwalker->internalid=0x5(5) 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-process-manager.c:440]: pidfile does not exist, process not started process->internalid=5 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Match: sec='', key='datadir', proct1='mysqld', pid1='5', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/5/data', pri=31, readonly=0 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2237]: inserting process into proctable proc_info->internalid=0x5(5) proc_info->os_pid=0xffffffff(-1) 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2238]: insert proc_info 0x9743bb0 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2517]: Process being stopped proc_info->processname=`mysqld' proc_info->internalid=0x5(5) 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-process-manager.c:756]: Process is NOT running: proc_info->internalid=5 proc_info->processname=`mysqld' proc_info->os_pid=-1 proc_info->exitstatus=0 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2481]: Update operation status vp_to_u_long_long(op_proc_status->runningconfigversion)=0x0(0) 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:215]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0xa(10) op_proc_status_copy->processid=0x5(5) operationstatus_to_string(op_proc_status_copy->operationstatus)=`finished' op_proc_status_copy->message=`process sucessfully stopped' ctx->current_operation_status->msg->force=0x0(0) 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2556]: Process processwalker->processname=`mysqld' processwalker->internalid=0x5(5) is already stopped, there is nothing to do 2011-02-10 11:23:14.857: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2669]: Still not done reconfig for config vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9743c28 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9743b50 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x9743c28 msg_count(out_msg)=0x2(2) 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb5300740 msg_count(a)=0x2(2) 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb5300870 msg_count(a)=0x1(1) 2011-02-10 11:23:14.862: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x9743c28 msg_count(*(&ctxt->outgoing.p))=0x2(2) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:14.863: (debug) vpfsm_process_message executed_key {0 10} last_key {0 10} 2011-02-10 11:23:14.863: (debug) incoming message app_data 0xb5300740 count 2 app_data 0xb5300740 group_id 94aaf91c vp count {0 9} node 0 app_key {0 11} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next 0xb5300870 app_data 0xb5300870 group_id 94aaf91c vp count {0 9} node 0 app_key {0 12} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:14.863: (debug) app_data 0xb5300740 count 1 app_data 0xb5300740 group_id 94aaf91c vp count {0 9} node 0 app_key {0 11} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) update_last_key setting last_key to {0 11} 2011-02-10 11:23:14.863: (debug) before_boot {0 2} 2011-02-10 11:23:14.863: (debug) last message repeated 1 times 2011-02-10 11:23:14.863: (debug) insert_log next_in 9 log_min {0 1} log_max {0 10} a->key {0 11} 2011-02-10 11:23:14.863: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb5300740 msg_count(a)=0x1(1) 2011-02-10 11:23:14.863: (debug) replace_app_data_single location target 0x9738340 app_data (nil) count 0 source 0xb5300740 app_data 0xb5300740 group_id 94aaf91c vp count {0 9} node 0 app_key {0 11} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:14.863: (debug) lookup_log_index key {0 11} returns 10 2011-02-10 11:23:14.863: (debug) lookup_log returns 0xb5300be8 lookup_log_index key {0 12} returns -1 2011-02-10 11:23:14.863: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb6d02020 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:14.863: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb6d02020 count 1 app_data 0xb6d02020 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:14.863: (debug) deliver message status 0 app_data 0xb5300740 count 1 app_data 0xb5300740 group_id 94aaf91c vp count {0 9} node 0 app_key {0 11} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:14.863: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:23:14.864: (debug) executed message {0 11} 2011-02-10 11:23:14.864: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb5300740 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:14.864: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb5300740 count 1 app_data 0xb5300740 group_id 94aaf91c vp count {0 9} node 0 app_key {0 11} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) source (nil) 2011-02-10 11:23:14.864: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:23:14.864: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 11 : mgr_process_operationstatus 2011-02-10 11:23:14.864: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:23:14.864: (debug) [T0x971fdf0 CMGR ]: new processopstatus for status->processid=0x4(4) status->host=`192.168.1.5' operationstatus_to_string(status->operationstatus)=`finished' 2011-02-10 11:23:14.864: (debug) app_data 0xb5300870 count 1 app_data 0xb5300870 group_id 94aaf91c vp count {0 9} node 0 app_key {0 12} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) update_last_key setting last_key to {0 12} 2011-02-10 11:23:14.864: (debug) before_boot {0 2} 2011-02-10 11:23:14.864: (debug) last message repeated 1 times 2011-02-10 11:23:14.864: (debug) insert_log next_in 10 log_min {0 1} log_max {0 11} a->key {0 12} 2011-02-10 11:23:14.864: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0x4(4) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0xa(10) 2011-02-10 11:23:14.864: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb5300870 msg_count(a)=0x1(1) 2011-02-10 11:23:14.865: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:14.865: (debug) replace_app_data_single location target 0x9738344 app_data (nil) count 0 source 0xb5300870 app_data 0xb5300870 group_id 94aaf91c vp count {0 9} node 0 app_key {0 12} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:14.865: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 executing {0 0} {0 0} 0 `' 2 192.168.1.5 executing {0 0} {0 0} 0 `' 3 192.168.1.5 executing {0 0} {0 0} 0 `' 4 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 5 192.168.1.5 executing {0 0} {0 0} 0 `' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:14.865: (debug) lookup_log_index key {0 12} returns 11 2011-02-10 11:23:14.865: (debug) lookup_log returns 0xb5300740 lookup_log_index key {0 13} returns -1 2011-02-10 11:23:14.865: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:14.865: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 11 2011-02-10 11:23:14.865: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb5300d10 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:14.865: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_process_operationstatus 2011-02-10 11:23:14.865: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1787]: new process operation status 2011-02-10 11:23:14.865: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb5300d10 count 1 app_data 0xb5300d10 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:14.865: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1450]: updating operation status procop->processid=4 procop->host=`192.168.1.5' operationstatus_to_string(procop->operationstatus)=`finished' procop->runningconfigversion={0 10} 2011-02-10 11:23:14.865: (debug) deliver message status 0 app_data 0xb5300870 count 1 app_data 0xb5300870 group_id 94aaf91c vp count {0 9} node 0 app_key {0 12} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:14.865: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:468]: status is config vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:14.865: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:23:14.866: (debug) executed message {0 12} 2011-02-10 11:23:14.866: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb5300870 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:14.866: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:23:14.866: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 12 : mgr_process_operationstatus 2011-02-10 11:23:14.866: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:23:14.866: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1919]: continue_type NO_NEWS 2011-02-10 11:23:14.866: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb5300870 count 1 app_data 0xb5300870 group_id 94aaf91c vp count {0 9} node 0 app_key {0 12} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) source (nil) 2011-02-10 11:23:14.866: (debug) [T0x971fdf0 CMGR ]: new processopstatus for status->processid=0x5(5) status->host=`192.168.1.5' operationstatus_to_string(status->operationstatus)=`finished' 2011-02-10 11:23:14.866: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:14.866: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0x5(5) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0xa(10) 2011-02-10 11:23:14.866: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:23:14.866: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:14.866: (debug) vp count {0 9} node 0 node 0 2011-02-10 11:23:14.866: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:23:14.866: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 executing {0 0} {0 0} 0 `' 2 192.168.1.5 executing {0 0} {0 0} 0 `' 3 192.168.1.5 executing {0 0} {0 0} 0 `' 4 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 5 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:14.866: (debug) 2011-02-10 11:23:14.866: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 12 2011-02-10 11:23:14.867: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:14.867: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_process_operationstatus 2011-02-10 11:23:14.867: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1787]: new process operation status 2011-02-10 11:23:14.867: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1450]: updating operation status procop->processid=5 procop->host=`192.168.1.5' operationstatus_to_string(procop->operationstatus)=`finished' procop->runningconfigversion={0 10} 2011-02-10 11:23:14.867: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:468]: status is config vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:14.867: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.004510 2011-02-10 11:23:14.867: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1919]: continue_type NO_NEWS 2011-02-10 11:23:14.958: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1946]: Processid process->processid=0x4(4) is now on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:14.958: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2795]: processwalker->processname=`mysqld' processwalker->internalid=0x4(4) is completed 2011-02-10 11:23:14.959: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1946]: Processid process->processid=0x5(5) is now on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:14.959: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2795]: processwalker->processname=`mysqld' processwalker->internalid=0x5(5) is completed 2011-02-10 11:23:14.959: (message) [T0x97194f8 RECFG]: req_id 4 Processes at startup sequence 3 done, going to next 2011-02-10 11:23:14.959: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2669]: Still not done reconfig for config vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:15.961: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1953]: Processid process->processid=0x2(2) is still not on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) vp_to_u_long_long(process->runningconfigversion)=0x0(0) 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2777]: ctx->curr_startseq=0x2(2) is not done for op_proc_status->processid=0x2(2) 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2481]: Update operation status vp_to_u_long_long(op_proc_status->runningconfigversion)=0x0(0) 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:215]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0xa(10) op_proc_status_copy->processid=0x2(2) operationstatus_to_string(op_proc_status_copy->operationstatus)=`finished' op_proc_status_copy->message=`process sucessfully stopped' ctx->current_operation_status->msg->force=0x0(0) 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2597]: my process processwalker->internalid=0x2(2) operationstatus_to_string(op_proc_status->operationstatus)=`finished' 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1043]: Start writing config file for process 'ndbd' 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=31, readonly=1 2011-02-10 11:23:15.962: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=34, readonly=1 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=31, readonly=1 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=35, readonly=1 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1156]: Done writing config file for process 'ndbd' 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2613]: config written successfully for processwalker->processname=`ndbd' processwalker->internalid=0x2(2) 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-process-manager.c:440]: pidfile does not exist, process not started process->internalid=2 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Match: sec='', key='datadir', proct1='ndbd', pid1='2', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/2/data', pri=31, readonly=0 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2237]: inserting process into proctable proc_info->internalid=0x2(2) proc_info->os_pid=0xffffffff(-1) 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2238]: insert proc_info 0x9743940 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2517]: Process being stopped proc_info->processname=`ndbd' proc_info->internalid=0x2(2) 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-process-manager.c:756]: Process is NOT running: proc_info->internalid=2 proc_info->processname=`ndbd' proc_info->os_pid=-1 proc_info->exitstatus=0 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2556]: Process processwalker->processname=`ndbd' processwalker->internalid=0x2(2) is already stopped, there is nothing to do 2011-02-10 11:23:15.963: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1953]: Processid process->processid=0x3(3) is still not on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) vp_to_u_long_long(process->runningconfigversion)=0x0(0) 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2777]: ctx->curr_startseq=0x2(2) is not done for op_proc_status->processid=0x3(3) 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2481]: Update operation status vp_to_u_long_long(op_proc_status->runningconfigversion)=0x0(0) 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:215]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0xa(10) op_proc_status_copy->processid=0x3(3) operationstatus_to_string(op_proc_status_copy->operationstatus)=`finished' op_proc_status_copy->message=`process sucessfully stopped' ctx->current_operation_status->msg->force=0x0(0) 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2597]: my process processwalker->internalid=0x3(3) operationstatus_to_string(op_proc_status->operationstatus)=`finished' 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1043]: Start writing config file for process 'ndbd' 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=31, readonly=1 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=36, readonly=1 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=31, readonly=1 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=37, readonly=1 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1156]: Done writing config file for process 'ndbd' 2011-02-10 11:23:15.964: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2613]: config written successfully for processwalker->processname=`ndbd' processwalker->internalid=0x3(3) 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-process-manager.c:440]: pidfile does not exist, process not started process->internalid=3 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Match: sec='', key='datadir', proct1='ndbd', pid1='3', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/3/data', pri=31, readonly=0 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2237]: inserting process into proctable proc_info->internalid=0x3(3) proc_info->os_pid=0xffffffff(-1) 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2238]: insert proc_info 0x9746660 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2517]: Process being stopped proc_info->processname=`ndbd' proc_info->internalid=0x3(3) 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-process-manager.c:756]: Process is NOT running: proc_info->internalid=3 proc_info->processname=`ndbd' proc_info->os_pid=-1 proc_info->exitstatus=0 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2556]: Process processwalker->processname=`ndbd' processwalker->internalid=0x3(3) is already stopped, there is nothing to do 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2817]: nomorestartseq is TRUE allShouldbeStopped is TRUE 2011-02-10 11:23:15.965: (message) last message repeated 1 times 2011-02-10 11:23:15.965: (message) [T0x97194f8 RECFG]: req_id 4 Processes at startup sequence 2 done, going to next 2011-02-10 11:23:15.965: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2669]: Still not done reconfig for config vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:16.082: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9743c98 2011-02-10 11:23:16.082: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9745d88 2011-02-10 11:23:16.082: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.082: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.082: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x9743c98 msg_count(out_msg)=0x2(2) 2011-02-10 11:23:16.083: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb5300578 msg_count(a)=0x2(2) 2011-02-10 11:23:16.083: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb53005c8 msg_count(a)=0x1(1) 2011-02-10 11:23:16.083: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x9743c98 msg_count(*(&ctxt->outgoing.p))=0x2(2) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.083: (debug) vpfsm_process_message executed_key {0 12} last_key {0 12} 2011-02-10 11:23:16.083: (debug) incoming message app_data 0xb5300578 count 2 app_data 0xb5300578 group_id 94aaf91c vp count {0 10} node 0 app_key {0 13} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next 0xb53005c8 app_data 0xb53005c8 group_id 94aaf91c vp count {0 10} node 0 app_key {0 14} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.083: (debug) app_data 0xb5300578 count 1 app_data 0xb5300578 group_id 94aaf91c vp count {0 10} node 0 app_key {0 13} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) update_last_key setting last_key to {0 13} 2011-02-10 11:23:16.083: (debug) before_boot {0 2} 2011-02-10 11:23:16.083: (debug) last message repeated 1 times 2011-02-10 11:23:16.083: (debug) insert_log next_in 11 log_min {0 1} log_max {0 12} a->key {0 13} 2011-02-10 11:23:16.083: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb5300578 msg_count(a)=0x1(1) 2011-02-10 11:23:16.083: (debug) replace_app_data_single location target 0x9738348 app_data (nil) count 0 source 0xb5300578 app_data 0xb5300578 group_id 94aaf91c vp count {0 10} node 0 app_key {0 13} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.083: (debug) lookup_log_index key {0 13} returns 12 2011-02-10 11:23:16.083: (debug) lookup_log returns 0xb5301168 lookup_log_index key {0 14} returns -1 2011-02-10 11:23:16.084: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb5300d10 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:16.084: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb5300d10 count 1 app_data 0xb5300d10 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:16.084: (debug) deliver message status 0 app_data 0xb5300578 count 1 app_data 0xb5300578 group_id 94aaf91c vp count {0 10} node 0 app_key {0 13} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.084: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:23:16.084: (debug) executed message {0 13} 2011-02-10 11:23:16.084: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb5300578 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.084: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:23:16.084: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb5300578 count 1 app_data 0xb5300578 group_id 94aaf91c vp count {0 10} node 0 app_key {0 13} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) source (nil) 2011-02-10 11:23:16.084: (debug) app_data 0xb53005c8 count 1 app_data 0xb53005c8 group_id 94aaf91c vp count {0 10} node 0 app_key {0 14} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) update_last_key setting last_key to {0 14} 2011-02-10 11:23:16.084: (debug) before_boot {0 2} 2011-02-10 11:23:16.084: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 13 : mgr_process_operationstatus 2011-02-10 11:23:16.084: (debug) before_boot {0 2} 2011-02-10 11:23:16.085: (debug) insert_log next_in 12 log_min {0 1} log_max {0 13} a->key {0 14} 2011-02-10 11:23:16.085: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:23:16.085: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb53005c8 msg_count(a)=0x1(1) 2011-02-10 11:23:16.085: (debug) [T0x971fdf0 CMGR ]: new processopstatus for status->processid=0x2(2) status->host=`192.168.1.5' operationstatus_to_string(status->operationstatus)=`finished' 2011-02-10 11:23:16.085: (debug) replace_app_data_single location target 0x973834c app_data (nil) count 0 source 0xb53005c8 app_data 0xb53005c8 group_id 94aaf91c vp count {0 10} node 0 app_key {0 14} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.085: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0x2(2) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0xa(10) 2011-02-10 11:23:16.085: (debug) lookup_log_index key {0 14} returns 13 2011-02-10 11:23:16.085: (debug) lookup_log returns 0xb5300578 lookup_log_index key {0 15} returns -1 2011-02-10 11:23:16.085: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:16.085: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:16.085: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_process_operationstatus 2011-02-10 11:23:16.085: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 executing {0 0} {0 0} 0 `' 2 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 3 192.168.1.5 executing {0 0} {0 0} 0 `' 4 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 5 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:16.085: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1787]: new process operation status 2011-02-10 11:23:16.086: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1450]: updating operation status procop->processid=2 procop->host=`192.168.1.5' operationstatus_to_string(procop->operationstatus)=`finished' procop->runningconfigversion={0 10} 2011-02-10 11:23:16.086: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:468]: status is config vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:16.086: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1919]: continue_type NO_NEWS 2011-02-10 11:23:16.086: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb5300d10 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:16.086: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 13 2011-02-10 11:23:16.086: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb5300d10 count 1 app_data 0xb5300d10 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:16.086: (debug) deliver message status 0 app_data 0xb53005c8 count 1 app_data 0xb53005c8 group_id 94aaf91c vp count {0 10} node 0 app_key {0 14} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.086: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:23:16.086: (debug) executed message {0 14} 2011-02-10 11:23:16.086: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:23:16.086: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 14 : mgr_process_operationstatus 2011-02-10 11:23:16.086: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:23:16.086: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb53005c8 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.086: (debug) [T0x971fdf0 CMGR ]: new processopstatus for status->processid=0x3(3) status->host=`192.168.1.5' operationstatus_to_string(status->operationstatus)=`finished' 2011-02-10 11:23:16.087: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0x3(3) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0xa(10) 2011-02-10 11:23:16.087: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb53005c8 count 1 app_data 0xb53005c8 group_id 94aaf91c vp count {0 10} node 0 app_key {0 14} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) source (nil) 2011-02-10 11:23:16.087: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:16.087: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.087: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:23:16.087: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 executing {0 0} {0 0} 0 `' 2 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 3 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 4 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 5 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:16.087: (debug) vp count {0 10} node 0 node 0 2011-02-10 11:23:16.087: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:23:16.087: (debug) 2011-02-10 11:23:16.087: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 14 2011-02-10 11:23:16.087: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:16.087: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_process_operationstatus 2011-02-10 11:23:16.087: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1787]: new process operation status 2011-02-10 11:23:16.087: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1450]: updating operation status procop->processid=3 procop->host=`192.168.1.5' operationstatus_to_string(procop->operationstatus)=`finished' procop->runningconfigversion={0 10} 2011-02-10 11:23:16.087: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.004978 2011-02-10 11:23:16.088: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:468]: status is config vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:16.088: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1919]: continue_type NO_NEWS 2011-02-10 11:23:16.166: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1953]: Processid process->processid=0x1(1) is still not on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) vp_to_u_long_long(process->runningconfigversion)=0x0(0) 2011-02-10 11:23:16.166: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2777]: ctx->curr_startseq=0x1(1) is not done for op_proc_status->processid=0x1(1) 2011-02-10 11:23:16.166: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2597]: my process processwalker->internalid=0x1(1) operationstatus_to_string(op_proc_status->operationstatus)=`executing' 2011-02-10 11:23:16.167: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1043]: Start writing config file for process 'ndb_mgmd' 2011-02-10 11:23:16.167: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=31, readonly=1 2011-02-10 11:23:16.167: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='Name', proct1='', pid1='', proct2='', pid2='', val='mycluster', pri=38, readonly=1 2011-02-10 11:23:16.167: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting removed: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=31, readonly=1 2011-02-10 11:23:16.167: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Setting appended: sec='system', key='ConfigGenerationNumber', proct1='', pid1='', proct2='', pid2='', val='10', pri=39, readonly=1 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-config-writer.c:1156]: Done writing config file for process 'ndb_mgmd' 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2613]: config written successfully for processwalker->processname=`ndb_mgmd' processwalker->internalid=0x1(1) 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-process-manager.c:440]: pidfile does not exist, process not started process->internalid=1 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-api-util.c:461]: Match: sec='', key='datadir', proct1='ndb_mgmd', pid1='1', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/1/data', pri=31, readonly=0 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2237]: inserting process into proctable proc_info->internalid=0x1(1) proc_info->os_pid=0xffffffff(-1) 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2238]: insert proc_info 0x97464e0 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2517]: Process being stopped proc_info->processname=`ndb_mgmd' proc_info->internalid=0x1(1) 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-process-manager.c:756]: Process is NOT running: proc_info->internalid=1 proc_info->processname=`ndb_mgmd' proc_info->os_pid=-1 proc_info->exitstatus=0 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2459]: Process is already stopped 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2481]: Update operation status vp_to_u_long_long(op_proc_status->runningconfigversion)=0x0(0) 2011-02-10 11:23:16.170: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:215]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0xa(10) op_proc_status_copy->processid=0x1(1) operationstatus_to_string(op_proc_status_copy->operationstatus)=`finished' op_proc_status_copy->message=`process sucessfully stopped' ctx->current_operation_status->msg->force=0x0(0) 2011-02-10 11:23:16.171: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2556]: Process processwalker->processname=`ndb_mgmd' processwalker->internalid=0x1(1) is already stopped, there is nothing to do 2011-02-10 11:23:16.171: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2817]: nomorestartseq is TRUE allShouldbeStopped is TRUE 2011-02-10 11:23:16.171: (debug) last message repeated 3 times 2011-02-10 11:23:16.171: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2669]: Still not done reconfig for config vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:16.187: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9743b50 2011-02-10 11:23:16.187: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.187: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.187: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x9743b50 msg_count(out_msg)=0x1(1) 2011-02-10 11:23:16.187: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb6d0e1b0 msg_count(a)=0x1(1) 2011-02-10 11:23:16.187: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x9743b50 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.188: (debug) vpfsm_process_message executed_key {0 14} last_key {0 14} 2011-02-10 11:23:16.188: (debug) incoming message app_data 0xb6d0e1b0 count 1 app_data 0xb6d0e1b0 group_id 94aaf91c vp count {0 11} node 0 app_key {0 15} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.188: (debug) app_data 0xb6d0e1b0 count 1 app_data 0xb6d0e1b0 group_id 94aaf91c vp count {0 11} node 0 app_key {0 15} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 208 next (nil) update_last_key setting last_key to {0 15} 2011-02-10 11:23:16.188: (debug) before_boot {0 2} 2011-02-10 11:23:16.188: (debug) last message repeated 1 times 2011-02-10 11:23:16.188: (debug) insert_log next_in 13 log_min {0 1} log_max {0 14} a->key {0 15} 2011-02-10 11:23:16.188: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb6d0e1b0 msg_count(a)=0x1(1) 2011-02-10 11:23:16.188: (debug) replace_app_data_single location target 0x9738350 app_data (nil) count 0 source 0xb6d0e1b0 app_data 0xb6d0e1b0 group_id 94aaf91c vp count {0 11} node 0 app_key {0 15} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.188: (debug) lookup_log_index key {0 15} returns 14 2011-02-10 11:23:16.188: (debug) lookup_log returns 0xb6d03878 lookup_log_index key {0 16} returns -1 2011-02-10 11:23:16.188: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb5300d10 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:16.188: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb5300d10 count 1 app_data 0xb5300d10 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:16.189: (debug) deliver message status 0 app_data 0xb6d0e1b0 count 1 app_data 0xb6d0e1b0 group_id 94aaf91c vp count {0 11} node 0 app_key {0 15} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) 2011-02-10 11:23:16.189: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:23:16.189: (debug) executed message {0 15} 2011-02-10 11:23:16.189: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb6d0e1b0 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.189: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:23:16.189: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb6d0e1b0 count 1 app_data 0xb6d0e1b0 group_id 94aaf91c vp count {0 11} node 0 app_key {0 15} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 208 next (nil) source (nil) 2011-02-10 11:23:16.189: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:16.189: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:23:16.189: (debug) vp count {0 11} node 0 node 0 2011-02-10 11:23:16.189: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 15 : mgr_process_operationstatus 2011-02-10 11:23:16.189: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:23:16.189: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:23:16.189: (debug) 2011-02-10 11:23:16.189: (debug) [T0x971fdf0 CMGR ]: new processopstatus for status->processid=0x1(1) status->host=`192.168.1.5' operationstatus_to_string(status->operationstatus)=`finished' 2011-02-10 11:23:16.189: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002440 2011-02-10 11:23:16.190: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0x1(1) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0xa(10) 2011-02-10 11:23:16.190: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:16.190: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:16.190: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_process_operationstatus 2011-02-10 11:23:16.190: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 2 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 3 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 4 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 5 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:16.190: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1787]: new process operation status 2011-02-10 11:23:16.190: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 15 2011-02-10 11:23:16.190: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1450]: updating operation status procop->processid=1 procop->host=`192.168.1.5' operationstatus_to_string(procop->operationstatus)=`finished' procop->runningconfigversion={0 10} 2011-02-10 11:23:16.190: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:468]: status is config vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:16.190: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1919]: continue_type NO_NEWS 2011-02-10 11:23:16.272: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1946]: Processid process->processid=0x1(1) is now on correct runningversion vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:16.272: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2795]: processwalker->processname=`ndb_mgmd' processwalker->internalid=0x1(1) is completed 2011-02-10 11:23:16.272: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2817]: nomorestartseq is TRUE allShouldbeStopped is TRUE 2011-02-10 11:23:16.272: (message) last message repeated 3 times 2011-02-10 11:23:16.272: (message) [T0x97194f8 RECFG]: req_id 4 Processes at startup sequence 1 done, going to next 2011-02-10 11:23:16.272: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2669]: Still not done reconfig for config vp_to_u_long_long(ctx->current_config->configversion)=0xa(10) 2011-02-10 11:23:17.275: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2817]: nomorestartseq is TRUE allShouldbeStopped is TRUE 2011-02-10 11:23:17.276: (message) last message repeated 4 times 2011-02-10 11:23:17.276: (message) [T0x97194f8 RECFG]: req_id 4 Processes at startup sequence 0 done, going to next 2011-02-10 11:23:17.276: (message) [T0x97194f8 RECFG]: req_id 4 Completed reconfig for config 10 2011-02-10 11:23:17.276: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:215]: sending procopstatus on xcom vp_to_u_long_long(op_proc_status_copy->runningconfigversion)=0xa(10) op_proc_status_copy->processid=0xffffffff(-1) operationstatus_to_string(op_proc_status_copy->operationstatus)=`finished' op_proc_status_copy->message=`' ctx->current_operation_status->msg->force=0x0(0) 2011-02-10 11:23:17.322: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0xb5300790 2011-02-10 11:23:17.322: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:17.322: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:17.322: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0xb5300790 msg_count(out_msg)=0x1(1) 2011-02-10 11:23:17.322: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb5300eb8 msg_count(a)=0x1(1) 2011-02-10 11:23:17.323: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0xb5300790 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:17.323: (debug) vpfsm_process_message executed_key {0 15} last_key {0 15} 2011-02-10 11:23:17.323: (debug) incoming message app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 12} node 0 app_key {0 16} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 180 next (nil) 2011-02-10 11:23:17.323: (debug) app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 12} node 0 app_key {0 16} consensus 0 local_execute 0 log_it 1 chosen 0 recover 1 expiry_time 10.000000 app_type length 180 next (nil) update_last_key setting last_key to {0 16} 2011-02-10 11:23:17.323: (debug) before_boot {0 2} 2011-02-10 11:23:17.323: (debug) last message repeated 1 times 2011-02-10 11:23:17.323: (debug) insert_log next_in 14 log_min {0 1} log_max {0 15} a->key {0 16} 2011-02-10 11:23:17.323: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb5300eb8 msg_count(a)=0x1(1) 2011-02-10 11:23:17.323: (debug) replace_app_data_single location target 0x9738354 app_data (nil) count 0 source 0xb5300eb8 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 12} node 0 app_key {0 16} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 180 next (nil) 2011-02-10 11:23:17.323: (debug) lookup_log_index key {0 16} returns 15 2011-02-10 11:23:17.323: (debug) lookup_log returns 0xb5300790 lookup_log_index key {0 17} returns -1 2011-02-10 11:23:17.323: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb6d038c8 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:17.323: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb6d038c8 count 1 app_data 0xb6d038c8 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:17.324: (debug) deliver message status 0 app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 12} node 0 app_key {0 16} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 180 next (nil) 2011-02-10 11:23:17.324: (debug) [T0x9706008 chass@message-broker.c:234]: message_broker(): putting operation status in cluster manager queue 2011-02-10 11:23:17.324: (debug) executed message {0 16} 2011-02-10 11:23:17.324: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb5300eb8 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:17.324: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 12} node 0 app_key {0 16} consensus 0 local_execute 0 log_it 1 chosen 1 recover 1 expiry_time 10.000000 app_type length 180 next (nil) source (nil) 2011-02-10 11:23:17.324: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:17.324: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:23:17.324: (debug) vp count {0 12} node 0 node 0 2011-02-10 11:23:17.324: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:23:17.324: (debug) 2011-02-10 11:23:17.324: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2aff(11007) mgr_process_operationstatus 2011-02-10 11:23:17.324: (message) [T0x971fdf0 CMGR ]: req_id 4 Start working on message @ 16 : mgr_process_operationstatus 2011-02-10 11:23:17.324: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4720]: clustermanager: getting processopstatus 2011-02-10 11:23:17.324: (debug) [T0x971fdf0 CMGR ]: new processopstatus for status->processid=0xffffffff(-1) status->host=`192.168.1.5' operationstatus_to_string(status->operationstatus)=`finished' 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4979]: updating operation status for procopstat->processid=0xffffffff(-1) procopstat->host=`192.168.1.5' operationstatus_to_string(procopstat->operationstatus)=`finished' vp_to_u_long_long(procopstat->deployedconfigversion)=0xa(10) 2011-02-10 11:23:17.325: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.002150 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 10} 2011-02-10 11:23:17.325: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2994]: reconfig_process_message 2011-02-10 11:23:17.325: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_create_cluster desiredconfigversion={0 10} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 2 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 3 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 4 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' 5 192.168.1.5 finished {0 10} {0 10} 0 `process sucessfully stopped' -1 192.168.1.5 finished {0 10} {0 10} 0 `' 2011-02-10 11:23:17.325: (message) [T0x971fdf0 CMGR ]: req_id 4 Operation finished for configversion 10 2011-02-10 11:23:17.325: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_process_operationstatus 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4674]: Trying to return success to client 2011-02-10 11:23:17.325: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1787]: new process operation status 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:358]: command_queue_push_success_simple cliaddr=127.0.0.1:43662 req_id 4 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 04 00 00 00 } 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:366]: Push simple success reply to command queue 2011-02-10 11:23:17.325: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1450]: updating operation status procop->processid=-1 procop->host=`192.168.1.5' operationstatus_to_string(procop->operationstatus)=`finished' procop->runningconfigversion={0 10} 2011-02-10 11:23:17.325: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4791]: unhandled_error->message=`An object with type opstat and name mycluster was not found in the repository cache' 2011-02-10 11:23:17.325: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:468]: status is config vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0xa(10) 2011-02-10 11:23:17.326: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2996]: continue_type NO_NEWS 2011-02-10 11:23:17.327: (message) [T0x971fdf0 CMGR ]: req_id 4 Finished working on message 16 2011-02-10 11:23:17.342: (debug) [T0x9706008 chass@message-broker.c:643]: Got reply object from command_queue, destined for &reply_->cliaddr=127.0.0.1:43662 req_id 4 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 04 00 00 00 } 2011-02-10 11:23:17.342: (debug) [T0x9706008 chass@message-broker.c:658]: Updating last replied req_id hw->req_id=0x3(3) reply_->cliaddr.req_id=0x4(4) 2011-02-10 11:23:17.342: (debug) [T0x9706008 chass@message-broker.c:666]: qcon=0xb6d02278 qcon->client->fd=0xe(14) reply_=0x97465b8 reply_={ &tp->cliaddr=127.0.0.1:43662 req_id 4 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 04 00 00 00 } reply={{ Command result }{ Cluster created successfully }}} 2011-02-10 11:23:17.342: (debug) [T0x9706008 chass@message-broker.c:682]: Before calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT 2011-02-10 11:23:17.342: (message) [T0x9706008 chass]: Returning success to client: 1 row(s): { { Cluster created successfully } } 2011-02-10 11:23:17.342: (debug) [T0x9706008 chass@message-broker.c:689]: Calling network_mysqld_con_handle 2011-02-10 11:23:17.343: (debug) [T0x9706008 chass@message-broker.c:705]: After calling con_handle: qcon->client->event.ev_events&EV_READ qcon->client->event.ev_flags&EVLIST_INIT qcon->state=10 2011-02-10 11:23:18.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndb_mgmd' proc->internalid=0x1(1) should be stopped, no status query 2011-02-10 11:23:18.751: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndbd' proc->internalid=0x2(2) should be stopped, no status query 2011-02-10 11:23:18.757: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndbd' proc->internalid=0x3(3) should be stopped, no status query 2011-02-10 11:23:18.757: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`mysqld' proc->internalid=0x4(4) should be stopped, no status query 2011-02-10 11:23:18.757: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`mysqld' proc->internalid=0x5(5) should be stopped, no status query 2011-02-10 11:23:18.757: (debug) [T0x97174c8 STAT @manager-status.c:355]: waiting max for new message on status queue SLEEPTIME=0x4c4b40(5000000) 2011-02-10 11:23:23.757: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndb_mgmd' proc->internalid=0x1(1) should be stopped, no status query 2011-02-10 11:23:23.757: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndbd' proc->internalid=0x2(2) should be stopped, no status query 2011-02-10 11:23:23.760: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`ndbd' proc->internalid=0x3(3) should be stopped, no status query 2011-02-10 11:23:23.760: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`mysqld' proc->internalid=0x4(4) should be stopped, no status query 2011-02-10 11:23:23.760: (debug) [T0x97174c8 STAT @manager-status.c:514]: proc->processname=`mysqld' proc->internalid=0x5(5) should be stopped, no status query 2011-02-10 11:23:23.760: (debug) [T0x97174c8 STAT @manager-status.c:355]: waiting max for new message on status queue SLEEPTIME=0x4c4b40(5000000) 2011-02-10 11:23:24.359: (message) [T0x9706008 chass]: Received command : start cluster mycluster 2011-02-10 11:23:24.359: (debug) [T0x9706008 chass@manager-commands.c:2404]: escaped_cmdline=`start cluster mycluster' 2011-02-10 11:23:24.359: (debug) [T0x9706008 chass@manager-commands.c:2523]: Adding operand to commands operand list : mycluster 2011-02-10 11:23:24.359: (debug) [T0x9706008 chass@manager-commands.c:698]: In handle_start_cluster 2011-02-10 11:23:24.359: (message) [T0x9706008 chass]: Handling request id 5 2011-02-10 11:23:24.359: (debug) [T0x9706008 chass@manager-commands.c:705]: INIT_CLIENT_ADDRESS &msg->client_address=127.0.0.1:43662 req_id 5 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 05 00 00 00 } 2011-02-10 11:23:24.359: (debug) [T0x9706008 chass@message-broker.c:128]: message_broker(): putting new config in cluster manager queue 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x17(23) api_start_cluster 2011-02-10 11:23:24.360: (message) [T0x971fdf0 CMGR ]: req_id 5 Start working on message @ 0 : api_start_cluster 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2160]: Verifying that local site exists 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2163]: Verifying that cluster exists 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2186]: Checking existing config 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @cluster-manager.c:2970]: Clearing process restart flags for new config 2011-02-10 11:23:24.360: (message) [T0x971fdf0 CMGR ]: Validating received cluster config 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:24.360: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) last message repeated 1 times 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) last message repeated 1 times 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:24.361: (debug) last message repeated 1 times 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:24.362: (debug) last message repeated 1 times 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1901]: Checking site site->sitename=`mysitel' hostname=`192.168.1.5' 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1915]: h->hostname=`192.168.1.5' hostname=`192.168.1.5' 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1840]: got match on name_to_check=`192.168.1.5' myent->h_name=`192.168.1.5' 2011-02-10 11:23:24.362: (debug) last message repeated 1 times 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:1620]: Copy process package from store 2011-02-10 11:23:24.362: (debug) last message repeated 4 times 2011-02-10 11:23:24.362: (debug) [T0x971fdf0 CMGR @manager-api-util.c:461]: Match: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=31, readonly=1 2011-02-10 11:23:24.363: (debug) [T0x971fdf0 CMGR @manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`ndb_mgmd' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:24.363: (debug) [T0x971fdf0 CMGR @manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`ndbd' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:24.363: (debug) last message repeated 1 times 2011-02-10 11:23:24.363: (debug) [T0x971fdf0 CMGR @manager-api-util.c:875]: strcmp DBGSTR(mcp->processname)=`mysqld' DBGSTR(MGMD)=`ndb_mgmd' 2011-02-10 11:23:24.363: (debug) last message repeated 1 times 2011-02-10 11:23:24.363: (debug) [T0x971fdf0 CMGR @manager-api-util.c:944]: Updating processes with url->str=`192.168.1.5:1186' 2011-02-10 11:23:24.363: (debug) [T0x971fdf0 CMGR @manager-api-util.c:461]: Setting removed: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=31, readonly=1 2011-02-10 11:23:24.364: (debug) [T0x971fdf0 CMGR @manager-api-util.c:461]: Setting appended: sec='system', key='PrimaryMGMNode', proct1='', pid1='', proct2='', pid2='', val='1', pri=26, readonly=1 2011-02-10 11:23:24.364: (debug) [T0x971fdf0 CMGR @cluster-manager.c:486]: xcom_async_send_msg im 0xb5300ec8 2011-02-10 11:23:24.364: (message) [T0x971fdf0 CMGR ]: req_id 5 Finished working on message 0 2011-02-10 11:23:24.390: (debug) [T0x9706008 chass@xcom_vpman.c:4119]: a=0x9748368 2011-02-10 11:23:24.390: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->accepted_msg)=NULL msg_count(*(&ctxt->accepted_msg))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:24.390: (debug) [T0x9706008 chass@xcom_vpman.c:3148]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:24.390: (debug) [T0x9706008 chass@xcom_vpman.c:2984]: replace_app_data_list *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) out_msg=0x9748368 msg_count(out_msg)=0x1(1) 2011-02-10 11:23:24.390: (debug) [T0x9706008 chass@xcom_vpman.c:2531]: replace_app_data_single *(&cache[a->app_key.low % 10000])=NULL msg_count(*(&cache[a->app_key.low % 10000]))=0x0(0) a=0xb5300eb8 msg_count(a)=0x1(1) 2011-02-10 11:23:24.390: (debug) [T0x9706008 chass@xcom_vpman.c:3169]: replace_app_data_single *(&ctxt->outgoing.p)=0x9748368 msg_count(*(&ctxt->outgoing.p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:24.390: (debug) vpfsm_process_message executed_key {0 16} last_key {0 16} 2011-02-10 11:23:24.390: (debug) incoming message app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 13} node 0 app_key {0 17} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) 2011-02-10 11:23:24.390: (debug) app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 13} node 0 app_key {0 17} consensus 0 local_execute 0 log_it 1 chosen 0 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) update_last_key setting last_key to {0 17} 2011-02-10 11:23:24.390: (debug) before_boot {0 2} 2011-02-10 11:23:24.390: (debug) last message repeated 1 times 2011-02-10 11:23:24.391: (debug) insert_log next_in 15 log_min {0 1} log_max {0 16} a->key {0 17} 2011-02-10 11:23:24.391: (debug) [T0x9706008 chass@xcom_vpman.c:2168]: replace_app_data_single *(&log->rec[log->next_in])=NULL msg_count(*(&log->rec[log->next_in]))=0x0(0) a=0xb5300eb8 msg_count(a)=0x1(1) 2011-02-10 11:23:24.391: (debug) replace_app_data_single location target 0x9738358 app_data (nil) count 0 source 0xb5300eb8 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 13} node 0 app_key {0 17} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) 2011-02-10 11:23:24.391: (debug) lookup_log_index key {0 17} returns 16 2011-02-10 11:23:24.391: (debug) lookup_log returns 0xb5300520 lookup_log_index key {0 18} returns -1 2011-02-10 11:23:24.391: (debug) [T0x9706008 chass@xcom_vpman.c:3627]: replace_app_data_single *(&ctxt->prev_node_group)=0xb5301400 msg_count(*(&ctxt->prev_node_group))=0x1(1) ctxt->node_group=0xb6d02e20 msg_count(ctxt->node_group)=0x1(1) 2011-02-10 11:23:24.391: (debug) lookup_log returns (nil) replace_app_data_single location target 0x972e610 app_data 0xb5301400 count 1 app_data 0xb5301400 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) source 0xb6d02e20 app_data 0xb6d02e20 group_id 94aaf91c vp count {0 1} node 0 app_key {0 2} consensus 1 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 xcom_boot_type length 1 192.168.1.5:1862 next (nil) 2011-02-10 11:23:24.391: (debug) deliver message status 0 app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 13} node 0 app_key {0 17} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) 2011-02-10 11:23:24.391: (debug) [T0x9706008 chass@message-broker.c:128]: message_broker(): putting new config in cluster manager queue 2011-02-10 11:23:24.391: (debug) executed message {0 17} 2011-02-10 11:23:24.391: (debug) [T0x9706008 chass@xcom_vpman.c:4069]: replace_app_data_single *(&p)=0xb5300eb8 msg_count(*(&p))=0x1(1) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:24.391: (debug) [T0x971fdf0 CMGR @cluster-manager.c:5575]: got new message with code mm->payload->code=0x2727(10023) mgr_start_cluster 2011-02-10 11:23:24.391: (debug) replace_app_data_single location target 0xbff57504 app_data 0xb5300eb8 count 1 app_data 0xb5300eb8 group_id 94aaf91c vp count {0 13} node 0 app_key {0 17} consensus 0 local_execute 0 log_it 1 chosen 1 recover 0 expiry_time 10.000000 app_type length 3520 next (nil) source (nil) 2011-02-10 11:23:24.391: (message) [T0x971fdf0 CMGR ]: req_id 5 Start working on message @ 17 : mgr_start_cluster 2011-02-10 11:23:24.391: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4251]: Verifying that local site exists 2011-02-10 11:23:24.391: (debug) [T0x9706008 chass@xcom_vpman.c:3967]: replace_app_data_single *(&ctxt->incoming)=NULL msg_count(*(&ctxt->incoming))=0x0(0) 0=NULL msg_count(0)=0x0(0) 2011-02-10 11:23:24.391: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4256]: Setting configversion as vpnum vp_to_u_long_long(config->configversion)=0x11(17) 2011-02-10 11:23:24.391: (debug) replace_app_data_single location target 0x972e604 app_data (nil) count 0 source (nil) 2011-02-10 11:23:24.391: (debug) vp count {0 13} node 0 node 0 2011-02-10 11:23:24.391: (message) [T0x9706008 chass]: Node set 1 2011-02-10 11:23:24.392: (debug) set_max_version {0 17} 2011-02-10 11:23:24.392: (debug) 2011-02-10 11:23:24.392: (debug) [T0x9706008 chass@xcom_vpman.c:4366]: vp_build_time 0.001644 2011-02-10 11:23:24.392: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4273]: handle_mgr_cluster_config trying to find correct cluster with name config->clustername=`mycluster' 2011-02-10 11:23:24.393: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:45]: Creating opstatus desiredplen=0x5(5) num_hosts=0x1(1) 2011-02-10 11:23:24.393: (debug) [T0x971fdf0 CMGR @manager-operation-status.c:104]: Operation not forced 2011-02-10 11:23:24.393: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:2994]: reconfig_process_message 2011-02-10 11:23:24.393: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1742]: handling new incoming message 2011-02-10 11:23:24.393: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1755]: got new message mgr_operationstatus 2011-02-10 11:23:24.393: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1792]: new operation status 2011-02-10 11:23:24.394: (debug) [T0x971fdf0 CMGR @cluster-manager.c:207]: save_return_address 2011-02-10 11:23:24.394: (debug) [T0x971fdf0 CMGR @cluster-manager.c:211]: client_address=127.0.0.1:43662 req_id 5 clinetaddrp[20]={ 02 00 aa 8e 7f 00 00 01 00 00 00 00 00 00 00 00 05 00 00 00 } 2011-02-10 11:23:24.394: (debug) [T0x97194f8 RECFG@manager-reconfigurator.c:1797]: new operationstatus vp_to_u_long_long(ctx->current_operation_status->desiredconfigversion)=0x11(17) 2011-02-10 11:23:24.394: (debug) [T0x97174c8 STAT @manager-status.c:361]: new message 2011-02-10 11:23:24.394: (debug) [T0x97174c8 STAT @manager-status.c:384]: Got new status queue message : opcode_to_string(mm->payload->code)=`mgr_start_cluster' 2011-02-10 11:23:24.394: (debug) [T0x97174c8 STAT @manager-status.c:399]: new config 2011-02-10 11:23:24.394: (debug) [T0x97174c8 STAT @manager-status.c:453]: DT: Not connecting to mgmd as mgmd_started==FALSE 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndb_mgmd' 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndbd' 2011-02-10 11:23:24.395: (debug) last message repeated 1 times 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`mysqld' 2011-02-10 11:23:24.395: (debug) last message repeated 1 times 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-status.c:199]: update_process_status() to unknown for process->internalid=0x1(1) 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-status.c:54]: queue status update to RECFG :status->clustername=`mycluster' status->nodetype=`ndb_mgmd' status->nodeid=1 processstatus_to_string(status->status)=`unknown' 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-status.c:72]: push batched status update to recfg 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-status.c:75]: send_updated_status(): batch->list.manager_message_array_len 1 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-status.c:81]: send_updated_status(): batch->list.manager_message_array_len 1 i 0 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-api-util.c:461]: Match: sec='', key='socket', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock', pri=31, readonly=0 2011-02-10 11:23:24.395: (debug) last message repeated 1 times 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @mysqld-process-communicator.c:82]: 1. Try connect using socket get_mysql_sock(config, process)=`/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock' 2011-02-10 11:23:24.395: (debug) [T0x97174c8 STAT @manager-api-util.c:461]: Match: sec='', key='socket', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock', pri=31, readonly=0 2011-02-10 11:23:24.396: (debug) [T0x97174c8 STAT @mysqld-process-communicator.c:89]: Failed to connect to mysqld: mysql_errno(mysql)=0x7d2(2002) mysql_error(mysql)=`Can't connect to local MySQL server through socket '/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock' (2)' 2011-02-10 11:23:24.396: (debug) [T0x97174c8 STAT @mysqld-process-communicator.c:92]: 2. Try connect using tcp get_mysql_port(config, process)=0xcea(3306) 2011-02-10 11:23:24.396: (debug) [T0x97174c8 STAT @manager-api-util.c:461]: Match: sec='', key='socket', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock', pri=31, readonly=0 2011-02-10 11:23:24.397: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4575]: Checking opstat on opstat->desiredconfigversion={0 17} 2011-02-10 11:23:24.397: (debug) [T0x971fdf0 CMGR @cluster-manager.c:4639]: Current operation_status: opcode=mgr_start_cluster desiredconfigversion={0 17} Id Host Status DepVer RunVer Code Message 1 192.168.1.5 executing {0 0} {0 0} 0 `' 2 192.168.1.5 executing {0 0} {0 0} 0 `' 3 192.168.1.5 executing {0 0} {0 0} 0 `' 4 192.168.1.5 executing {0 0} {0 0} 0 `' 5 192.168.1.5 executing {0 0} {0 0} 0 `' -1 192.168.1.5 executing {0 0} {0 0} 0 `' 2011-02-10 11:23:24.397: (message) [T0x971fdf0 CMGR ]: req_id 5 Finished working on message 17 2011-02-10 11:23:24.397: (debug) [T0x97174c8 STAT @mysqld-process-communicator.c:99]: Failed to connect to mysqld: mysql_errno(mysql)=0x7d3(2003) mysql_error(mysql)=`Can't connect to MySQL server on '192.168.1.5' (111)' 2011-02-10 11:23:24.397: (debug) [T0x97174c8 STAT @manager-api-util.c:461]: Match: sec='', key='socket', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock', pri=31, readonly=0 2011-02-10 11:23:24.397: (debug) last message repeated 1 times 2011-02-10 11:23:24.397: (debug) [T0x97174c8 STAT @mysqld-process-communicator.c:102]: 3. Try connect using socket once more get_mysql_sock(config, process)=`/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock' 2011-02-10 11:23:24.397: (debug) [T0x97174c8 STAT @manager-api-util.c:461]: Match: sec='', key='socket', proct1='mysqld', pid1='4', proct2='', pid2='', val='/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock', pri=31, readonly=0 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @mysqld-process-communicator.c:109]: Failed to connect to mysqld: mysql_errno(mysql)=0x7d2(2002) mysql_error(mysql)=`Can't connect to local MySQL server through socket '/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock' (2)' 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:224]: error report while connecting: error->message=`Failed to connect to database: Error: Can't connect to local MySQL server through socket '/home/billy/mysq/mcm2/manager/clusters/mycluster/4/mysql4.sock' (2)' 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:254]: do not have a valid mysql pointer 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndb_mgmd' 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`ndbd' 2011-02-10 11:23:24.398: (debug) last message repeated 1 times 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-api-util.c:371]: creating new status struct status->clustername=`mycluster' process->hostaddress=`192.168.1.5' process->processname=`mysqld' 2011-02-10 11:23:24.398: (debug) last message repeated 1 times 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:199]: update_process_status() to stopped for process->internalid=0x4(4) 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:54]: queue status update to RECFG :status->clustername=`mycluster' status->nodetype=`mysqld' status->nodeid=4 processstatus_to_string(status->status)=`stopped' 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:72]: push batched status update to recfg 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:75]: send_updated_status(): batch->list.manager_message_array_len 1 2011-02-10 11:23:24.398: (debug) [T0x97174c8 STAT @manager-status.c:81]: send_updated_status(): batch->list.manager_message_array_len 1 i 0