Attachment 672810 Details for Bug 892112 – development.log

development.log

file_892112.txt (text/plain), 13.12 KB, created by Rony Gong 🔥 on 2013-01-05 09:05:31 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Rony Gong 🔥

Created: 2013-01-05 09:05:31 UTC

Size: 13.12 KB

patch

obsolete

>2013-01-05 01:23:41.847 [DEBUG] MOPED: 127.0.0.1:27017 QUERY        database=openshift_broker_dev collection=applications selector={"$query"=>{"group_instances.gears._id"=>"50e7a11c776856a80800019f"}, "$orderby"=>{:_id=>1}} flags=[:slave_ok] limit=-1 skip=0 fields=nil (1.2658ms) (pid:4024)
>2013-01-05 01:23:41.855 [DEBUG] MOPED: 127.0.0.1:27017 QUERY        database=openshift_broker_dev collection=domains selector={"$query"=>{"_id"=>"50e79621776856a808000004"}, "$orderby"=>{:_id=>1}} flags=[:slave_ok] limit=-1 skip=0 fields=nil (0.6990ms) (pid:4024)
>2013-01-05 01:23:41.884 [DEBUG] MOPED: 127.0.0.1:27017 QUERY        database=openshift_broker_dev collection=cloud_users selector={"$query"=>{"_id"=>"50e7960b776856a808000001"}, "$orderby"=>{:_id=>1}} flags=[:slave_ok] limit=-1 skip=0 fields=nil (1.0107ms) (pid:4024)
>2013-01-05 01:23:41.887 [DEBUG] MOPED: 127.0.0.1:27017 QUERY        database=openshift_broker_dev collection=domains selector={"owner_id"=>"50e7960b776856a808000001"} flags=[:slave_ok] limit=0 skip=0 fields=nil (0.7370ms) (pid:4024)
>2013-01-05 01:23:41.889 [DEBUG] MOPED: 127.0.0.1:27017 QUERY        database=openshift_broker_dev collection=domains selector={"user_ids"=>"50e7960b776856a808000001"} flags=[:slave_ok] limit=0 skip=0 fields=nil (0.6070ms) (pid:4024)
>2013-01-05 01:23:41.892 [DEBUG] MOPED: 127.0.0.1:27017 COMMAND      database=openshift_broker_dev command={:findAndModify=>"locks", :query=>{"user_id"=>"50e7960b776856a808000001", "app_ids"=>{"$nin"=>["50e7a11c776856a80800019f"]}}, :new=>true, :update=>{"$push"=>{:app_ids=>"50e7a11c776856a80800019f"}}} (1.1728ms) (pid:4024)
>2013-01-05 01:23:42.545 [DEBUG] DEBUG: Source district uuid: 50e79b17776856de32000001 (pid:4024)
>2013-01-05 01:23:42.546 [DEBUG] DEBUG: Destination district uuid: 50e79b17776856de32000001 (pid:4024)
>2013-01-05 01:23:42.546 [DEBUG] DEBUG: District unchanged keeping uid (pid:4024)
>2013-01-05 01:23:42.705 [DEBUG] DEBUG: Getting existing app 'dancer' status before moving (pid:4024)
>2013-01-05 01:23:42.715 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x000000064920e0> (pid:4024)
>2013-01-05 01:23:42.716 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"perl-5.10", :action=>"status", :args=>"'dancer' 'qgong8' '50e7a11c776856a80800019f'"}, ip-10-100-222-253, {'identity' => ip-10-100-222-253}) (pid:4024)
>2013-01-05 01:23:43.455 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000006719250 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-100-222-253", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"CLIENT_RESULT: Application 'dancer' is either stopped or inaccessible\nATTR: status=ALREADY_STOPPED\nATTR: quota_blocks=1048576\nATTR: quota_files=40000\n", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:23:43.457 [DEBUG] DEBUG: Gear component 'perl-5.10' was running (pid:4024)
>2013-01-05 01:23:43.461 [DEBUG] DEBUG: Stopping existing app cartridge 'perl-5.10' before moving (pid:4024)
>2013-01-05 01:23:43.464 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x000000068b75a8> (pid:4024)
>2013-01-05 01:23:43.464 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"perl-5.10", :action=>"stop", :args=>"'dancer' 'qgong8' '50e7a11c776856a80800019f'"}, ip-10-100-222-253, {'identity' => ip-10-100-222-253}) (pid:4024)
>2013-01-05 01:23:44.761 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x000000066aa468 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-100-222-253", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"httpd (no pid file) not running\nATTR: status=ALREADY_STOPPED\n", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:23:44.762 [DEBUG] DEBUG: Force stopping existing app cartridge 'perl-5.10' before moving (pid:4024)
>2013-01-05 01:23:44.764 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x00000005b67ce0> (pid:4024)
>2013-01-05 01:23:44.764 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"openshift-origin-node", :action=>"force-stop", :args=>{"--with-app-uuid"=>"50e7a11c776856a80800019f", "--with-container-uuid"=>"50e7a11c776856a80800019f"}}, ip-10-100-222-253, {'identity' => ip-10-100-222-253}) (pid:4024)
>2013-01-05 01:23:45.245 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x000000066ec390 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-100-222-253", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:23:45.271 [DEBUG] DEBUG: Creating new account for gear 'dancer' on ip-10-38-21-76 (pid:4024)
>2013-01-05 01:23:45.284 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x00000005bbdfa0> (pid:4024)
>2013-01-05 01:23:45.286 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"openshift-origin-node", :action=>"app-create", :args=>{"--with-app-uuid"=>"50e7a11c776856a80800019f", "--with-app-name"=>"dancer", "--with-container-uuid"=>"50e7a11c776856a80800019f", "--with-container-name"=>"dancer", "--with-namespace"=>"qgong8", "--with-uid"=>1008}}, ip-10-38-21-76, {'identity' => ip-10-38-21-76}) (pid:4024)
>2013-01-05 01:23:46.845 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000006410040 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-38-21-76", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:23:46.854 [DEBUG] DEBUG: Moving content for app 'dancer', gear 'dancer' to ip-10-38-21-76 (pid:4024)
>2013-01-05 01:23:46.854 [DEBUG] DEBUG: Moving content for app 'dancer', gear 'dancer' to ip-10-38-21-76 (pid:4024)
>2013-01-05 01:23:51.421 [DEBUG] Agent pid 4415
>unset SSH_AUTH_SOCK;
>unset SSH_AGENT_PID;
>echo Agent pid 4415 killed; (pid:4024)
>2013-01-05 01:23:51.422 [DEBUG] DEBUG: Moving system components for app 'dancer', gear 'dancer' to ip-10-38-21-76 (pid:4024)
>2013-01-05 01:23:52.323 [DEBUG] Agent pid 4485
>unset SSH_AUTH_SOCK;
>unset SSH_AGENT_PID;
>echo Agent pid 4485 killed; (pid:4024)
>2013-01-05 01:23:52.330 [DEBUG] DEBUG: Restarting httpd proxy for 'perl-5.10' on ip-10-38-21-76 (pid:4024)
>2013-01-05 01:23:52.332 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x00000006af0ea0> (pid:4024)
>2013-01-05 01:23:52.332 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"abstract", :action=>"restart-httpd-proxy", :args=>"'dancer' 'qgong8' '50e7a11c776856a80800019f'"}, ip-10-38-21-76, {'identity' => ip-10-38-21-76}) (pid:4024)
>2013-01-05 01:23:53.616 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000006b11d08 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-38-21-76", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:23:53.657 [DEBUG] DEBUG: Starting cartridge 'perl-5.10' in 'dancer' after move on ip-10-38-21-76 (pid:4024)
>2013-01-05 01:23:53.699 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x000000068bcaa8> (pid:4024)
>2013-01-05 01:23:53.711 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"perl-5.10", :action=>"start", :args=>"'dancer' 'qgong8' '50e7a11c776856a80800019f'"}, ip-10-38-21-76, {'identity' => ip-10-38-21-76}) (pid:4024)
>2013-01-05 01:23:56.249 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000006a6c6c8 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-38-21-76", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:23:56.291 [DEBUG] DEBUG: Fixing DNS and mongo for gear 'dancer' after move (pid:4024)
>2013-01-05 01:23:56.293 [DEBUG] DEBUG: Changing server identity of 'dancer' from 'ip-10-100-222-253' to 'ip-10-38-21-76' (pid:4024)
>2013-01-05 01:23:56.313 [DEBUG] DEBUG: DYNECT Login with path: /REST/Session/ (pid:4024)
>2013-01-05 01:23:56.775 [DEBUG] DEBUG: DYNECT Response: {"status": "success", "data": {"token": "oaO4a/Gf8R/N/VWYe80bzpYJr+glj7o5ZeiqiFvkMLvnpMXWdI05ww8omDy+TpAr68Yba0na6EKgMTU7rH56xkmFZaT0WN+epObUJMuN6sxrsTxBOh47CKpYC3j3UwGkc7IB7dNRJAULFPUbFJ0s8LHGjOx4YpZs", "version": "3.3.7"}, "job_id": 242445047, "msgs": [{"INFO": "login: Login successful", "SOURCE": "BLL", "ERR_CD": null, "LVL": "INFO"}]} (pid:4024)
>2013-01-05 01:23:56.775 [DEBUG] DEBUG: DYNECT Response data: {"token"=>"oaO4a/Gf8R/N/VWYe80bzpYJr+glj7o5ZeiqiFvkMLvnpMXWdI05ww8omDy+TpAr68Yba0na6EKgMTU7rH56xkmFZaT0WN+epObUJMuN6sxrsTxBOh47CKpYC3j3UwGkc7IB7dNRJAULFPUbFJ0s8LHGjOx4YpZs", "version"=>"3.3.7"} (pid:4024)
>2013-01-05 01:23:56.837 [DEBUG] DEBUG: Public ip being modified 'ec2-107-22-30-206.compute-1.amazonaws.com' to app 'dancer' (pid:4024)
>2013-01-05 01:23:56.838 [DEBUG] DEBUG: DYNECT put/post with path: /REST/CNAMERecord/rhcloud.com/dancer-qgong8.dev.rhcloud.com/ json data: {"rdata":{"cname":"ec2-107-22-30-206.compute-1.amazonaws.com"},"ttl":"60"} and headers: {"Content-Type"=>"application/json", "Auth-Token"=>"[hidden]"} (pid:4024)
>2013-01-05 01:23:57.475 [DEBUG] DEBUG: DYNECT Response: {"status": "success", "data": {"zone": "rhcloud.com", "ttl": 60, "fqdn": "dancer-qgong8.dev.rhcloud.com", "record_type": "CNAME", "rdata": {"cname": "ec2-107-22-30-206.compute-1.amazonaws.com."}, "record_id": 0}, "job_id": 242445055, "msgs": [{"INFO": "update: Record updated", "SOURCE": "BLL", "ERR_CD": null, "LVL": "INFO"}]} (pid:4024)
>2013-01-05 01:23:57.476 [DEBUG] DEBUG: DYNECT Response data: {"zone"=>"rhcloud.com", "ttl"=>60, "fqdn"=>"dancer-qgong8.dev.rhcloud.com", "record_type"=>"CNAME", "rdata"=>{"cname"=>"ec2-107-22-30-206.compute-1.amazonaws.com."}, "record_id"=>0} (pid:4024)
>2013-01-05 01:23:57.476 [DEBUG] DEBUG: DYNECT put/post with path: /REST/Zone/rhcloud.com/ json data: {"publish":"true"} and headers: {"Content-Type"=>"application/json", "Auth-Token"=>"[hidden]"} (pid:4024)
>2013-01-05 01:23:59.289 [DEBUG] DEBUG: DYNECT Response: {"status": "success", "data": {"zone_type": "Primary", "serial_style": "increment", "serial": 3874399, "zone": "rhcloud.com"}, "job_id": 242445063, "msgs": [{"INFO": "publish: rhcloud.com published", "SOURCE": "BLL", "ERR_CD": null, "LVL": "INFO"}]} (pid:4024)
>2013-01-05 01:23:59.289 [DEBUG] DEBUG: DYNECT Response data: {"zone_type"=>"Primary", "serial_style"=>"increment", "serial"=>3874399, "zone"=>"rhcloud.com"} (pid:4024)
>2013-01-05 01:23:59.289 [DEBUG] DEBUG: DYNECT delete with path: /REST/Session/ and headers: {"Content-Type"=>"application/json", "Auth-Token"=>"[hidden]"} (pid:4024)
>2013-01-05 01:23:59.685 [DEBUG] DEBUG: DYNECT Response: {"status": "success", "data": {}, "job_id": 242445072, "msgs": [{"INFO": "logout: Logout successful", "SOURCE": "BLL", "ERR_CD": null, "LVL": "INFO"}]} (pid:4024)
>2013-01-05 01:23:59.685 [DEBUG] DEBUG: DYNECT Response data: {} (pid:4024)
>2013-01-05 01:23:59.686 [DEBUG] Running publishers (pid:4024)
>2013-01-05 01:23:59.812 [DEBUG] DEBUG: Output of parallel execute: [{:tag=>"50e7a12a776856a8080001b6", :gear=>"50e7a11c776856a80800019f", :job=>{:cartridge=>"openshift-origin-node", :action=>"connector-execute", :args=>{"--gear-uuid"=>"50e7a11c776856a80800019f", "--cart-name"=>"perl-5.10", "--hook-name"=>"get-proxy-url", "--input-args"=>"dancer qgong8 50e7a11c776856a80800019f"}}, :result_stdout=>"Could not find /usr/libexec/openshift/cartridges/perl-5.10/info/connection-hooks/get-proxy-url", :result_stderr=>"Could not find /usr/libexec/openshift/cartridges/perl-5.10/info/connection-hooks/get-proxy-url", :result_exit_code=>127}], exitcode: 0, from: ip-10-100-222-253 (pid:4024)
>2013-01-05 01:23:59.814 [DEBUG] Running subscribers (pid:4024)
>2013-01-05 01:23:59.815 [DEBUG] Connections done (pid:4024)
>2013-01-05 01:23:59.838 [DEBUG] MOPED: 127.0.0.1:27017 UPDATE       database=openshift_broker_dev collection=applications selector={"_id"=>"50e7a11c776856a80800019f"} update={"$set"=>{"updated_at"=>2013-01-05 06:23:59 UTC, "group_instances.0.gears.0.server_identity"=>"ip-10-38-21-76"}} flags=[] (8.9486ms) (pid:4024)
>2013-01-05 01:23:59.839 [DEBUG] DEBUG: Deconfiguring old app 'dancer' on ip-10-100-222-253 after move (pid:4024)
>2013-01-05 01:23:59.841 [DEBUG] DEBUG: rpc_exec_direct: rpc_client=#<MCollective::RPC::Client:0x00000006e5ad98> (pid:4024)
>2013-01-05 01:23:59.842 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"openshift-origin-node", :action=>"app-destroy", :args=>{"--with-app-uuid"=>"50e7a11c776856a80800019f", "--with-app-name"=>"dancer", "--with-container-uuid"=>"50e7a11c776856a80800019f", "--with-container-name"=>"dancer", "--with-namespace"=>"qgong8", "--skip-hooks"=>true}}, ip-10-100-222-253, {'identity' => ip-10-100-222-253}) (pid:4024)
>2013-01-05 01:24:04.989 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000006ea7ff8 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-100-222-253", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0}}>] (pid:4024)
>2013-01-05 01:24:04.997 [DEBUG] Successfully moved 'dancer' with gear uuid '50e7a11c776856a80800019f' from 'ip-10-100-222-253' to 'ip-10-38-21-76' (pid:4024)
>2013-01-05 01:24:05.730 [DEBUG] MOPED: 127.0.0.1:27017 COMMAND      database=openshift_broker_dev command={:findAndModify=>"locks", :query=>{"user_id"=>"50e7960b776856a808000001", "locked"=>false, "app_ids"=>{"$in"=>["50e7a11c776856a80800019f"]}}, :new=>false, :update=>{"$pop"=>{:app_ids=>"50e7a11c776856a80800019f"}}} (7.7207ms) (pid:4024)
>^C

Actions: View

Attachments on bug 892112: 672810