Flexible environment "Unexpected error during VM startup" in Production folowing "periodic restart of VM version."
1,000 views
Skip to first unread message
Karl Tinawi
Feb 26, 2018, 9:04:13 AM2/26/18
to Google App Engine
Hi team,
Now after this point, and when the VM tries to startup again, it appears to go in to a perpetual restart cycle, Note the following error messages
This is perhaps somewhat related to this topic here.
We've recently experienced delays in deploying our PHP flexible app whereby "gcloud deploy" times-out waiting for the new instance to start. This has been somewhat managed - by manually deleting the failing VM and starting the version again manually - up until now as it only impacted deployments. Today, we discovered that our production application experienced the same thing during what appears to be scheduled maintenance.
Digging a little deeper, this entry appeared in our log at 06:16:33 this morning:
2018-02-26 06:16:33.396 GMT
App Engine
vm_administrative_task_started
default:29-1
appengine-admin-noreply@google.com
Starting periodic restart of VM version.Followed by:
2018-02-26 06:17:12.579 GMT
App Engine
vm_administrative_task_started
default:29-1
appengine-admin-noreply@google.com
Restarting batch of VMs as part of rolling restart.The VM running our production application then proceeded to shutdown following this log entry:
2018-02-26 06:17:20.469 GMT------------------------VM shutdown initiated-----------------------
Now after this point, and when the VM tries to startup again, it appears to go in to a perpetual restart cycle, Note the following error messages
We had no idea the system was down until a user reported the issue to us - which is hugely bad for us (!). We've learnt the following from this:-
- We clearly need an UpTime check (!!) - We've now updated stackdriver to do this for us.
- Currently our flexible environment utilises only a single instance - we clearly need to add more for redundancy.
We initially thought that our issues pertaining to App Engine were isolated to the deployment, and not ongoing maintenance... which is clearly not the case.
Having fallen back to our previous production version (which thankfully did start), I can't start our latest version on the platform. This is causing us a lot of concern (and headache):
Will post some logs shortly.
Thanks for looking in this.
Karl
George (Cloud Platform Support)
Feb 26, 2018, 4:58:14 PM2/26/18
to google-a...@googlegroups.com
Hello Karl,
The errors you describe would correspond to what is expected if health checks fail: "App Engine sends periodic health check requests to confirm that an instance has been successfully deployed, and to check that a running instance maintains a healthy status. Each health check must be answered within a specified time interval. An instance is unhealthy when it fails to respond to a specified number of consecutive health check requests. An unhealthy instance will not receive any client requests, but health checks will still be sent. If an unhealthy instance continues to fail to respond to a predetermined number of consecutive health checks, it will be restarted." This is described on the "How Instances are Managed" page, and it might explain what you call a "perpetual restart cycle".
A copy of your app.yaml would be appreciated. How are health checks set up in app.yaml?
How does your app deal with health checks? A copy of the relevant part of your code might help a lot.
What were the changes you performed in your app's code, prior to deployment?
Karl Tinawi
Feb 27, 2018, 4:08:32 AM2/27/18
to Google App Engine
Hi George,
Thanks for getting back to me.
Apologies I may not have made myself clear. The outage we experienced yesterday was nothing to do with a deployment. The app was healthy and in a running state before the incident. We know this because of the request logs (HTTP 200 response codes) shortly prior.
As mentioned previously, the issue we saw in our production environment was as a result of scheduled maintenance it seems. My understanding on this is that our app should migrate prior to this happening without any downtime...
After this log entry:
2018-02-26 06:17:12.579 GMTApp Enginevm_administrative_task_starteddefault:29-1appengine-admin-noreply@google.comRestarting batch of VMs as part of rolling restart..
...
2018-02-26 06:17:20.469 GMT------------------------VM shutdown initiated-----------------------
...
A 2018/02/26 06:17:46 [notice] 43#0: signal 15 (SIGTERM) received, exiting
A 2018/02/26 06:17:46 [notice] 46#0: exiting
A 2018/02/26 06:17:46 [notice] 46#0: exit
A 2018/02/26 06:17:46 [notice] 45#0: exiting
A 2018/02/26 06:17:46 [notice] 45#0: exit
A 2018/02/26 06:17:46 [notice] 48#0: exiting
A 2018/02/26 06:17:46 [notice] 48#0: exit
A 2018/02/26 06:17:46 [notice] 47#0: exiting
A 2018/02/26 06:17:46 [notice] 43#0: signal 17 (SIGCHLD) received
A 2018/02/26 06:17:46 [notice] 43#0: worker process 48 exited with code 0
A 2018/02/26 06:17:46 [notice] 43#0: signal 29 (SIGIO) received
A 2018/02/26 06:17:46 [notice] 47#0: exit
A 2018/02/26 06:17:46 [notice] 43#0: signal 17 (SIGCHLD) received
A 2018/02/26 06:17:46 [notice] 43#0: worker process 45 exited with code 0
A 2018/02/26 06:17:46 [notice] 43#0: worker process 47 exited with code 0
A 2018/02/26 06:17:46 [notice] 43#0: signal 17 (SIGCHLD) received
A 2018/02/26 06:17:46 [notice] 43#0: worker process 46 exited with code 0
A 2018/02/26 06:17:46 [notice] 43#0: exit
A [26-Feb-2018 06:17:46] NOTICE: Terminating ...
A 2018/02/26 06:17:46 Client closed local connection on /cloudsql/onkho-web-app-live:europe-west2:sql-2-app-live
A 2018/02/26 06:17:46 Client closed local connection on /cloudsql/onkho-web-app-live:europe-west2:sql-2-app-live
A 2018/02/26 06:17:46 Client closed local connection on /cloudsql/onkho-web-app-live:europe-west2:sql-2-app-live
A 2018/02/26 06:17:46 Client closed local connection on /cloudsql/onkho-web-app-live:europe-west2:sql-2-app-live
A [26-Feb-2018 06:17:46] NOTICE: exiting, bye-bye!
A 2018/02/26 06:17:46 Client closed local connection on /cloudsql/onkho-web-app-live:europe-west2:sql-2-app-live
A 2018-02-26 06:17:46,138 WARN received SIGTERM indicating exit request
A 2018-02-26 06:17:46,139 INFO waiting for cron, nginx, php-fpm, onkho-laravel-worker to die
A 2018-02-26 06:17:46,139 INFO stopped: cron (terminated by SIGTERM)
A 2018-02-26 06:17:46,151 INFO stopped: nginx (exit status 0)
A 2018-02-26 06:17:46,153 INFO stopped: onkho-laravel-worker (terminated by SIGTERM)
A 2018-02-26 06:17:46,167 INFO stopped: php-fpm (exit status 0)
A Feb 26 06:17:46 aef-default-29--1-k42h vm_runtime_init: Feb 26 06:17:46 Pure compute version. Should skip _ah/start or stop.
A Triggering app shutdown handlers.
A Feb 26 06:17:46 Pure compute version. Should skip _ah/start or stop.
A vm_runtime_init: Feb 26 06:17:46 Pure compute version. Should skip _ah/start or stop.
A Sending SIGTERM to app.
A 20704b75609990329d423a1cd9119c6ba21540f99389ff34695679040a72b340
A Sending SIGKILL to app.
A Waiting for termination, 1 seconds remaining.
A Error response from daemon: Cannot kill container 20704b75609990329d423a1cd9119c6ba21540f99389ff34695679040a72b340: Container 20704b75609990329d423a1cd9119c6ba21540f99389ff34695679040a72b340 is not running
A App shutdown handlers done.
A Feb 26 06:17:46 aef-default-29--1-k42h kernel: [366361.132793] docker0: port 5(veth988044c) entered disabled state
A Feb 26 06:17:46 aef-default-29--1-k42h kernel: [366361.212724] docker0: port 5(veth988044c) entered disabled state
A Feb 26 06:17:46 aef-default-29--1-k42h kernel: [366361.219942] device veth988044c left promiscuous mode
A Feb 26 06:17:46 aef-default-29--1-k42h kernel: [366361.225720] docker0: port 5(veth988044c) entered disabled state
A Sending SIGUSR1 to fluentd to trigger a log flush.
A 97431e4987be07596f0abd4d098f086b740c772afd301544d832d85feb928561
A -------------------------------------------------------------------
A Feb 26 06:17:47 aef-default-29--1-k42h shutdownscript: Finished running shutdown script /var/run/google.shutdown.script
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.620746] docker0: port 3(veth4b7b426) entered disabled state
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.627123] docker0: port 4(veth3712639) entered disabled state
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.704671] docker0: port 3(veth4b7b426) entered disabled state
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.711774] device veth4b7b426 left promiscuous mode
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.717767] docker0: port 3(veth4b7b426) entered disabled state
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.748729] docker0: port 4(veth3712639) entered disabled state
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.756766] device veth3712639 left promiscuous mode
A Feb 26 06:17:47 aef-default-29--1-k42h kernel: [366362.762596] docker0: port 4(veth3712639) entered disabled state
The VM then goes in to a perpetual cycle of the following with the following:
A The instance aef-default-29--1-k42h with Debian based image was created for version 29-1
A ====== Unexpected error during VM startup ======
A ==== Dump of VM runtime system logs follows ====
A == Output of 'docker ps -a' ==
A CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
A ========= rebooting. ========================
A ------------------------VM shutdown initiated-----------------------
A Current app health: 0
A Beginning service lameduck.
A Triggering app shutdown handlers.
A Sending SIGUSR1 to fluentd to trigger a log flush.
A {"textPayload":"","insertId":"8w5bzng2xz7vna","resource":{"type":"gae_app","labels":{"module_id":"default","project_id":"onkho-web-app-live","version_id":"29-1"}},"timestamp":"2018-02-26T06:19:22.800492049Z","labels":{"compute.googleapis.com/resource_type":"instance","compute.googleapis.com/resource…
A -------------------------------------------------------------------
A --------------App was unhealthy, grabbing debug logs---------------
A Container CID file not found.
A -------------------------------------------------------------------
A -------------------------Tail of app logs--------------------------
A App logs not found.
A -------------------------------------------------------------------
A -------------------------Additional debug info--------------------------
A cat: /home/vmagent/onkho-web-app-live_29-1-407822458647357645.env: No such file or directory
A Instance has machine type of custom-4-8192 has 4 vCPU and 8192 Mb memory. App can use Mb memory.
A VM memory consumption:
A total used free shared buffers cached
A Mem: 8005 271 7734 0 15 116
A -/+ buffers/cache: 139 7866
A Swap: 0 0 0
A VM disk usage:
A Filesystem Type 1K-blocks Used Available Use% Mounted on
A rootfs rootfs 10188088 4544604 5102916 48% /
A udev devtmpfs 10240 0 10240 0% /dev
A /dev/sda1 ext4 10188088 4544604 5102916 48% /
A /dev/sda1 ext4 10188088 4544604 5102916 48% /var/lib/docker/aufs
A Processes running on the VM:
A top - 06:19:22 up 0 min, 0 users, load average: 0.22, 0.06, 0.02
A Tasks: 94 total, 1 running, 93 sleeping, 0 stopped, 0 zombie
A %Cpu(s): 2.0 us, 2.9 sy, 0.0 ni, 87.2 id, 8.0 wa, 0.0 hi, 0.0 si, 0.0 st
A KiB Mem: 8197596 total, 285776 used, 7911820 free, 15376 buffers
A KiB Swap: 0 total, 0 used, 0 free, 119816 cached
A {"textPayload":"","insertId":"8w5bzng2xz7vo2","resource":{"type":"gae_app","labels":{"project_id":"onkho-web-app-live","version_id":"29-1","module_id":"default"}},"timestamp":"2018-02-26T06:19:22.800492077Z","labels":{"compute.googleapis.com/resource_type":"instance","compute.googleapis.com/resource…
A PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
A 4311 root 20 0 70732 20m 6620 S 46.0 0.3 0:00.11 python
A 1 root 20 0 10664 1612 1480 S 0.0 0.0 0:00.79 init
A 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
A 3 root 20 0 0 0 0 S 0.0 0.0 0:00.03 ksoftirqd/0
A 4 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0
A 5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
A 6 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/u8:0
A 7 root 20 0 0 0 0 S 0.0 0.0 0:00.08 rcu_sched
A 8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
A 9 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/0
A 10 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/0
A 11 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/1
A 12 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/1
A 13 root 20 0 0 0 0 S 0.0 0.0 0:00.03 ksoftirqd/1
A 14 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0
A 15 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0H
A 16 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/2
A 17 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/2
A 18 root 20 0 0 0 0 S 0.0 0.0 0:00.01 ksoftirqd/2
A 19 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/2:0
A 20 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/2:0H
A 21 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/3
A 22 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/3
A 23 root 20 0 0 0 0 S 0.0 0.0 0:00.02 ksoftirqd/3
A 24 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/3:0
A 25 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/3:0H
A 26 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 khelper
A 27 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfs
A 28 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 netns
A 29 root 20 0 0 0 0 S 0.0 0.0 0:00.00 khungtaskd
A 30 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 writeback
A 31 root 25 5 0 0 0 S 0.0 0.0 0:00.00 ksmd
A 32 root 39 19 0 0 0 S 0.0 0.0 0:00.00 khugepaged
A 33 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 crypto
A 34 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kintegrityd
A 35 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 bioset
A 36 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kblockd
A 37 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/1:1
A 38 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kswapd0
A 39 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 vmstat
A 40 root 20 0 0 0 0 S 0.0 0.0 0:00.00 fsnotify_mark
A 46 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kthrotld
A 47 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/0:1
A 48 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 ipv6_addrconf
A 49 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/1:2
A 50 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 deferwq
A 51 root 20 0 0 0 0 S 0.0 0.0 0:00.01 kworker/u8:1
A 61 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/2:1
A 634 root 20 0 0 0 0 S 0.0 0.0 0:00.00 scsi_eh_0
A 635 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 scsi_tmf_0
A 636 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/u8:2
A 637 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/3:1
A 647 root 0 -20 0 0 0 S 0.0 0.0 0:00.02 kworker/0:1H
A 680 root 20 0 0 0 0 S 0.0 0.0 0:00.00 jbd2/sda1-8
A 681 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 ext4-rsv-conver
A 838 root 20 0 21928 2980 1848 S 0.0 0.0 0:00.07 udevd
A 863 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/2:1H
A 882 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/3:1H
A 1452 root 20 0 21924 2668 1636 S 0.0 0.0 0:00.00 udevd
A 1453 root 20 0 21924 2672 1636 S 0.0 0.0 0:00.00 udevd
A 1516 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:1H
A 1529 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kpsmoused
A 1532 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/2:2
A 1533 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/2:3
A 2666 root 20 0 9968 3248 952 S 0.0 0.0 0:00.00 dhclient
A 2747 root 20 0 18988 2068 1812 S 0.0 0.0 0:00.00 rpcbind
A 2778 statd 20 0 23360 2492 2032 S 0.0 0.0 0:00.00 rpc.statd
A 2783 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 rpciod
A 2785 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 nfsiod
A 2792 root 20 0 25312 212 4 S 0.0 0.0 0:00.00 rpc.idmapd
A 3082 root 20 0 115m 2760 2380 S 0.0 0.0 0:00.02 rsyslogd
A 3221 root 20 0 4132 1552 1408 S 0.0 0.0 0:00.00 acpid
A 3333 ntp 20 0 34892 4304 3708 S 0.0 0.1 0:00.00 ntpd
A 3358 root 20 0 20424 2140 1900 S 0.0 0.0 0:00.00 cron
A 3574 root 20 0 167m 41m 34m S 0.0 0.5 0:00.46 kubelet
A 3577 root 20 0 517m 32m 20m S 0.0 0.4 0:00.39 docker
A 3626 root 20 0 336m 9256 7664 S 0.0 0.1 0:00.03 docker-containe
A 3725 root 20 0 49332 9332 2892 S 0.0 0.1 0:00.00 manage_accounts
A 3726 root 20 0 4112 1228 1124 S 0.0 0.0 0:00.00 startpar
A 3767 root 20 0 53732 10m 4164 S 0.0 0.1 0:00.00 manage_accounts
A 3969 root 20 0 4196 1488 1324 S 0.0 0.0 0:00.00 rc
A 3978 root 20 0 12788 2576 1932 S 0.0 0.0 0:00.02 startpar
A 3980 root 20 0 4196 1568 1408 S 0.0 0.0 0:00.00 google-accounts
A 3983 root 20 0 4196 1560 1408 S 0.0 0.0 0:00.00 google-startup-
A 4013 root 20 0 9252 2332 2168 S 0.0 0.0 0:00.00 run-shutdown-sc
A 4044 root 20 0 4108 1444 1352 S 0.0 0.0 0:00.15 start-stop-daem
A 4131 root 20 0 9260 2232 2068 S 0.0 0.0 0:00.00 run-scripts
A 4134 root 20 0 9264 2308 2084 S 0.0 0.0 0:00.00 run-scripts
A 4144 root 20 0 9268 2192 1960 S 0.0 0.0 0:00.00 run-scripts
A 4145 root 20 0 4104 420 340 S 0.0 0.0 0:00.00 logger
A 4147 root 20 0 9460 2516 2092 S 0.0 0.0 0:00.00 run-scripts
A 4309 root 20 0 9468 2584 2148 S 0.0 0.0 0:00.00 run-scripts
A 4310 root 20 0 9460 1952 1528 S 0.0 0.0 0:00.00 run-scripts
A 4349 root 20 0 21676 2316 2000 R 0.0 0.0 0:00.00 top
A Additional thread and heap info may be available in app.shutdown if you are using a supported client library.
A -------------------------------------------------------------------
Obviously at this early stage in the boot process no docker image has been loaded and no code of ours has been executed.
For reference, this is our app.yaml:
# Define the runtime and environment
runtime: custom
env: flex
# Runtime configuration
runtime_config:
document_root: public
enable_stackdriver_integration: true
nginx_conf_override: nginx.conf
nginx_conf_http_include: nginx-http.conf
nginx_conf_include: nginx-app.conf
# Don't deploy the below files.
skip_files:
- ^(.*)\.(log|gitignore|DS_Store)$
- app.staging.yaml
- .staging.env
- .idea/
- scripts/(.*)\.sh$
- vendor/
# Resource Requirements
# https://cloud.google.com/appengine/docs/flexible/php/configuring-your-app-with-app-yaml#resource-settings
resources:
cpu: 4
memory_gb: 7.6
# Health checks
health_check:
enable_health_check: false
# Scaling Requirements
# https://cloud.google.com/appengine/docs/flexible/php/configuring-your-app-with-app-yaml#services
manual_scaling:
instances: 1
beta_settings:
cloud_sql_instances: "XXX"
Let me know if there is anything else you need from me.
Thanks again for your help George, looking forward to hearing from you.
Kind regards,
Karl
On Monday, February 26, 2018 at 9:58:14 PM UTC, George (Cloud Platform Support) wrote:
Hello Karl,The errors you describe would correspond to what is expected if health check fail: "App Engine sends periodic health check requests to confirm that an instance has been successfully deployed, and to check that a running instance maintains a healthy status. Each health check must be answered within a specified time interval. An instance is unhealthy when it fails to respond to a specified number of consecutive health check requests. An unhealthy instance will not receive any client requests, but health checks will still be sent. If an unhealthy instance continues to fail to respond to a predetermined number of consecutive health checks, it will be restarted." This is described on the "How Instances are Managed" page, and it might explain what you call a "perpetual restart cycle".
George (Cloud Platform Support)
Feb 27, 2018, 7:52:06 PM2/27/18
to Google App Engine
Hello Karl,
You seem to indicate that the outage is a one-time event, and that there is no other similar occurrence as yet. If this is so, to prevent similar unwanted events in future, you may configure your app for health checks, in detail. For reference, the "Configuring your App with app.yaml" should prove of great help. In your app.yaml, you can specify either liveness check (choosing appropriate parameter values):
liveness_check:
path: "/liveness_check"
check_interval_sec: 30
timeout_sec: 4
failure_threshold: 2
success_threshold: 2
or readiness check:
readiness_check:
path: "/readiness_check"
check_interval_sec: 5
timeout_sec: 4
failure_threshold: 2
success_threshold: 2
app_start_timeout_sec: 300
It is worthwhile noting that the usual way of specifying PHP for you app is:
runtime: php //This setting is required. It is the name of the App Engine language runtime used by this application. To specify PHP, use php
env: flex
You app uses: runtime: custom , by contrast.
You may also switch to automatic scaling from manual, and one only instance. If this makes a difference in your app's behavior, the information would help us with debugging.
Karl Tinawi
Feb 28, 2018, 3:12:09 PM2/28/18
to Google App Engine
Hi George,
Yes that's correct - it's happened once outside of deployments.
To answer your questions sir:
- We require a custom PHP installation in order to make use of modules that are missing from Google's offering. I've not checked the latest list of extension but it may be that we may be able to move back to using the standard PHP image so I'll check this for sure.
- Scaling is another challenge that we're looking and we're certainly aware that we need to move to auto scaling for contingency etc...
- I'll test configuring the readiness check and report back if we notice any difference in behaviour.
Were the logs helpful? I'd be grateful if you could shed some light on the investigation your end. This is the first time we've noticed an issue such as this during the maintenance process, which should be innocuous and invisible to us.
At this point I'm unsure if the issues we face during deployments are related to the incident that happened with our running app, which continue to occur daily. It's worth noting that the behaviour of the VM is identical (in the way of the abrupt restarts as it's trying to boot). I may look at trying a test deployment using another image and seeing if that helps.
Many thanks again,
Karl
Message has been deleted
Karl Tinawi
Feb 28, 2018, 4:37:21 PM2/28/18
to Google App Engine
Hi George,
The most obvious question I have at this point, is why? Why would this resolve it the issue? I can only guess that this could be related to the new style health/liveness checks being enabled by default but we had not executed:
or provided the liveness_check/readiness_check blocks in our yaml file? I've only just learnt about these new updated health checks here as it's not something we keep up-to-date with once we have a desired configuration so am concerned that there was a backwards compatibility issue here.
I was able to do a test deployment tonight by defining the new health checks as you recommended.
Before I continue - my test for this based on performing a deployment as we see the exact same behaviour there with the VM starting up and crashing as we did with the incident on Monday.
The good news is this has seemingly completely resolved our deployment issue - in that they are once again successful in a reasonable amount of time, rather than timing out and failing because of the aforementioned. So at this point I'm semi confident that it has also resolved the issue we experienced on Monday when the VM was restarted and couldn't start up again. Difficult to prove this one currently from my side.
I replaced the legacy health_check block in our .yaml file with the following:-
liveness_check:
path: "/_ah/health"
initial_delay_sec: 300
check_interval_sec: 5
timeout_sec: 5
failure_threshold: 3
success_threshold: 1
readiness_check:
path: "/login"
app_start_timeout_sec: 300
check_interval_sec: 30
timeout_sec: 5
failure_threshold: 3
success_threshold: 1
The most obvious question I have at this point, is why? Why would this resolve it the issue? I can only guess that this could be related to the new style health/liveness checks being enabled by default but we had not executed:
gcloud beta app update --split-health-checks --project [YOUR_PROJECT_ID]
or provided the liveness_check/readiness_check blocks in our yaml file? I've only just learnt about these new updated health checks here as it's not something we keep up-to-date with once we have a desired configuration so am concerned that there was a backwards compatibility issue here.
I'm performing a couple more deployments to satisfy myself that this is not a fluke.
Many thanks again and looking forward to hearing from you.
Karl
George Suceveanu
Feb 28, 2018, 4:40:49 PM2/28/18
to google-a...@googlegroups.com
Hi Karl,
If your app starts up without issues, the health checks would not matter. There are issues with your app's start up process, that you need to address. For coding-related issues, you are at an advantage posting to stackoverflow or similar forums, where you can get expert help from active programmers.
On 28 February 2018 at 16:23, Karl Tinawi <ka...@onkho.com> wrote:
Hi George,I was able to do a test deployment tonight by defining the new health checks as you recommended.Before I continue - my test for this based on performing a deployment as we see the exact same behaviour there with the VM starting up and crashing as we did with the incident on Monday.The good news is this has seemingly completely resolved our deployment issue - in that they are once again successful in a reasonable amount of time, rather than timing out and failing because of the aforementioned. So at this point I'm semi confident that it has also resolved the issue we experienced on Monday when the VM was restarted and couldn't start up again. Difficult to prove this one currently from my side.I replaced the legacy health_check block in our .yaml file with the following:-
path: "/_ah/health"
initial_delay_sec: 300
check_interval_sec: 5
timeout_sec: 5
failure_threshold: 3
success_threshold: 1
readiness_check:
path: "/login"
app_start_timeout_sec: 300
check_interval_sec: 30
timeout_sec: 5
failure_threshold: 3
success_threshold: 1
The most obvious question I have at this point, is why? Why would this resolve it the issue? I can only guess that this could be related to the new style health/liveness checks being enabled by default but we had not executed:
or provided the liveness_check/readiness_check blocks in our yaml file? I've only just learnt about these new updated health checks here as it's not something we keep up-to-date with once we have a desired configuration so am concerned that there was a backwards compatibility issue here.I'm performing a couple more deployments to satisfy myself that this is not a fluke.
As a side question I see these entries in our logs now since activating the new health checks:
These don't seem to be obeying the configuration I had defined (as per above code snippets). Most notably the path and interval?I'd like to learn if I'm doing anything wrong here or if there is an explanation.Many thanks again and looking forward to hearing from you.Karl
On Wednesday, February 28, 2018 at 8:12:09 PM UTC, Karl Tinawi wrote:
To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/fe551f25-65ef-4eef-a1fd-7e53e44f0f06%40googlegroups.com.--
You received this message because you are subscribed to a topic in the Google Groups "Google App Engine" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/google-appengine/5mKOn6RzRFY/unsubscribe.
To unsubscribe from this group and all its topics, send an email to google-appengine+unsubscribe@googlegroups.com.
To post to this group, send email to google-appengine@googlegroups.com.
Visit this group at https://groups.google.com/group/google-appengine.
George (Cloud Platform Support)
Feb 28, 2018, 4:41:09 PM2/28/18
to Google App Engine
Karl Tinawi
Feb 28, 2018, 5:05:36 PM2/28/18
to Google App Engine
Hi George,
It's definitely not the code or our app's startup process as far as I'm aware because this issue is before our docker image is even pulled or any code of ours executed. The logs should show that clearly.
The change I applied as per your suggested relating to the health checks did not involve any code change whatsoever and yet the VM starts normally now. The only difference being that I now see the new health check requests in the logs during the startup process.
I'll continue testing and reply with any additional findings.
I'd be grateful if you could shed some more light on the incident in question as I still don't have an answer as to what happened.
To unsubscribe from this group and all its topics, send an email to google-appengi...@googlegroups.com.
To post to this group, send email to google-a...@googlegroups.com.
Karl Tinawi
Feb 28, 2018, 5:55:44 PM2/28/18
to Google App Engine
Hi George,
I was celebrating prematurely :( We're still facing the issue it seems. I'm trying to deploy the same health check change to our production project.
Please could you take a look at this log output? :
I App Engine CreateVersion default:30-1 karl@onkho.com {"@type":"type.googleapis.com/google.cloud.audit.AuditLog","status":{},"authenticationInfo":{"principalEmail":"ka...@onkho.com"},"requestMetadata":{"callerIp":"217.45.176.239","callerSuppliedUserAgent":"google-cloud-sdk x_Tw5K8nnjoRAqULM9PFAC2b gcloud/190.0.1 command/gcloud.app.deploy invocation-id/7… App Engine CreateVersion default:30-1 ka...@onkho.com
A The instance aef-default-30--1-m6mp with Debian based image was created for version 30-1
A ====== Unexpected error during VM startup ======
A ==== Dump of VM runtime system logs follows ====
A == Output of 'docker ps -a' ==
A CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
A ========= rebooting. ========================
A ------------------------VM shutdown initiated-----------------------
A Current app health: 0
A Beginning service lameduck.
A Triggering app shutdown handlers.
A Sending SIGUSR1 to fluentd to trigger a log flush.
A {"textPayload":"","insertId":"5kdt4ig2zxfdhb","resource":{"type":"gae_app","labels":{"project_id":"onkho-web-app-live","version_id":"30-1","module_id":"default"}},"timestamp":"2018-02-28T22:36:35.183183909Z","labels":{"compute.googleapis.com/resource_type":"instance","compute.googleapis.com/resource…
A -------------------------------------------------------------------
A --------------App was unhealthy, grabbing debug logs---------------
A Container CID file not found.
A -------------------------------------------------------------------
A -------------------------Tail of app logs--------------------------
A App logs not found.
A -------------------------------------------------------------------
A -------------------------Additional debug info--------------------------
A cat: /home/vmagent/onkho-web-app-live_30-1-407983590104907782.env: No such file or directory
A Instance has machine type of custom-4-8192 has 4 vCPU and 8192 Mb memory. App can use Mb memory.
A VM memory consumption:
A total used free shared buffers cached
A Mem: 8005 276 7728 0 14 117
A -/+ buffers/cache: 144 7861
A Swap: 0 0 0
A VM disk usage:
A Filesystem Type 1K-blocks Used Available Use% Mounted on
A rootfs rootfs 10188088 4544604 5102916 48% /
A udev devtmpfs 10240 0 10240 0% /dev
A /dev/sda1 ext4 10188088 4544604 5102916 48% /
A /dev/sda1 ext4 10188088 4544604 5102916 48% /var/lib/docker/aufs
A Processes running on the VM:
A top - 22:36:35 up 0 min, 0 users, load average: 0.48, 0.13, 0.04
A Tasks: 95 total, 1 running, 94 sleeping, 0 stopped, 0 zombie
A %Cpu(s): 2.1 us, 3.1 sy, 0.0 ni, 85.6 id, 9.1 wa, 0.0 hi, 0.0 si, 0.0 st
A KiB Mem: 8197596 total, 287356 used, 7910240 free, 15352 buffers
A KiB Swap: 0 total, 0 used, 0 free, 120448 cached
A {"textPayload":"","insertId":"5kdt4ig2zxfdi3","resource":{"type":"gae_app","labels":{"module_id":"default","project_id":"onkho-web-app-live","version_id":"30-1"}},"timestamp":"2018-02-28T22:36:35.183183937Z","labels":{"compute.googleapis.com/resource_type":"instance","compute.googleapis.com/resource…
A PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
A 1 root 20 0 10664 1644 1508 S 0.0 0.0 0:00.82 init
A 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
A 3 root 20 0 0 0 0 S 0.0 0.0 0:00.04 ksoftirqd/0
A 4 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0
A 5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
A 6 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/u8:0
A 7 root 20 0 0 0 0 S 0.0 0.0 0:00.09 rcu_sched
A 8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
A 9 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/0
A 10 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/0
A 11 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/1
A 12 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/1
A 13 root 20 0 0 0 0 S 0.0 0.0 0:00.03 ksoftirqd/1
A 14 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0
A 15 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0H
A 16 root rt 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/2
A 17 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/2
A 18 root 20 0 0 0 0 S 0.0 0.0 0:00.02 ksoftirqd/2 A 49 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/2:1
A 50 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 deferwq
A 51 root 20 0 0 0 0 S 0.0 0.0 0:00.01 kworker/u8:1
A 632 root 20 0 0 0 0 S 0.0 0.0 0:00.00 scsi_eh_0
A 633 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 scsi_tmf_0
A 634 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/u8:2
A 635 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/3:1
A 645 root 0 -20 0 0 0 S 0.0 0.0 0:00.02 kworker/0:1H
A 673 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/0:2
A 679 root 20 0 0 0 0 S 0.0 0.0 0:00.00 jbd2/sda1-8
A 680 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 ext4-rsv-conver
A 719 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:1H
A 726 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/2:1H
A 839 root 20 0 21928 3068 1956 S 0.0 0.0 0:00.09 udevd
A 1167 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/3:1H
A 1451 root 20 0 21924 2620 1580 S 0.0 0.0 0:00.00 udevd
A 1452 root 20 0 21924 2624 1580 S 0.0 0.0 0:00.00 udevd
A 1484 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/1:2
A 1489 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kpsmoused
A 1490 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/3:2
A 1528 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/2:2
A 2668 root 20 0 9968 3180 888 S 0.0 0.0 0:00.00 dhclient
A 2749 root 20 0 18988 2016 1760 S 0.0 0.0 0:00.00 rpcbind
A 2780 statd 20 0 23360 2496 2032 S 0.0 0.0 0:00.00 rpc.statd
A 2785 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 rpciod
A 2787 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 nfsiod
A 2796 root 20 0 25312 216 4 S 0.0 0.0 0:00.00 rpc.idmapd
A 3086 root 20 0 115m 2668 2304 S 0.0 0.0 0:00.03 rsyslogd
A 3176 root 20 0 4132 1584 1440 S 0.0 0.0 0:00.00 acpid
A 3289 ntp 20 0 34892 4272 3672 S 0.0 0.1 0:00.00 ntpd
A 3360 root 20 0 20424 2152 1912 S 0.0 0.0 0:00.00 cron
A 3528 root 20 0 143m 42m 35m S 0.0 0.5 0:00.59 kubelet
A 3573 root 20 0 501m 32m 20m S 0.0 0.4 0:00.46 docker
A 3636 root 20 0 336m 9180 7600 S 0.0 0.1 0:00.03 docker-containe
A 3722 root 20 0 4112 1224 1124 S 0.0 0.0 0:00.00 startpar
A 3723 root 20 0 49332 9328 2888 S 0.0 0.1 0:00.00 manage_accounts
A 3750 root 20 0 53732 10m 4144 S 0.0 0.1 0:00.00 manage_accounts
A 3969 root 20 0 4196 1488 1328 S 0.0 0.0 0:00.00 rc
A 3978 root 20 0 12788 2576 1932 S 0.0 0.0 0:00.03 startpar
A 3980 root 20 0 4196 1460 1300 S 0.0 0.0 0:00.00 google-accounts
A 3983 root 20 0 4196 1564 1408 S 0.0 0.0 0:00.00 google-startup-
A 4008 root 20 0 4108 1520 1432 S 0.0 0.0 0:00.15 start-stop-daem
A 4011 root 20 0 9252 2356 2192 S 0.0 0.0 0:00.00 run-shutdown-sc
A 4082 root 20 0 9260 2252 2088 S 0.0 0.0 0:00.00 run-scripts
A 4085 root 20 0 9264 2244 2020 S 0.0 0.0 0:00.00 run-scripts
A 4095 root 20 0 9268 2240 2008 S 0.0 0.0 0:00.00 run-scripts
A 4096 root 20 0 4104 476 396 S 0.0 0.0 0:00.00 logger
A 4098 root 20 0 9460 2508 2080 S 0.0 0.0 0:00.00 run-scripts
A 4281 root 20 0 9464 2516 2084 S 0.0 0.0 0:00.00 run-scripts
A 4282 root 20 0 9460 1956 1528 S 0.0 0.0 0:00.00 run-scripts
A 4283 root 20 0 70732 20m 6660 S 0.0 0.3 0:00.12 python
A 4321 root 20 0 21676 2240 1932 R 0.0 0.0 0:00.00 top
A Additional thread and heap info may be available in app.shutdown if you are using a supported client library.
A -------------------------------------------------------------------
If I can't get to the bottom of this then we'll be forced to go back to compute engine.
Any help would be greatly appreciated.
Karl Tinawi
Mar 2, 2018, 7:02:49 AM3/2/18
to Google App Engine
Hi George,
On a successful boot of the VM we see the following:
A ------------------------------------------------------------------- A The instance aef-default-30-sp8t with Debian based image was created for version 30 A Feb 28 23:07:05 aef-default-30-sp8t kernel: imklog 5.8.11, log source = /proc/kmsg started. A Feb 28 23:07:05 aef-default-30-sp8t rsyslogd: [origin software="rsyslogd" swVersion="5.8.11" x-pid="2965" x-info="http://www.rsyslog.com"] start A Feb 28 23:07:05 aef-default-30-sp8t kernel: [ 0.000000] Initializing cgroup subsys cpuset A Feb 28 23:07:05 aef-default-30-sp8t kernel: [ 0.000000] Initializing cgroup subsys cpu A Feb 28 23:07:05 aef-default-30-sp8t kernel: [ 0.000000] Initializing cgroup subsys cpuacct
...On Wednesday, February 28, 2018 at 10:55:44 PM UTC, Karl Tinawi wrote:
Hi George,
I was celebrating prematurely :( We're still facing the issue it seems. I'm trying to deploy the same health check change to our production project.Please could you take a look at this log output? :
A -------------------------------------------------------------------
A --------------App was unhealthy, grabbing debug logs---------------
A Container CID file not found.
A -------------------------------------------------------------------
A -------------------------Tail of app logs--------------------------
A App logs not found.
A -------------------------------------------------------------------
A -------------------------Additional debug info--------------------------
A cat: /home/vmagent/onkho-web-app-live_30-1-407983590104907782.env: No such file or directory
A Instance has machine type of custom-4-8192 has 4 vCPU and 8192 Mb memory. App can use Mb memory.
A VM memory consumption:
A -/+ buffers/cache: 144 7861
A Swap: 0 0 0
A VM disk usage:
A Filesystem Type 1K-blocks Used Available Use% Mounted on
A rootfs rootfs 10188088 4544604 5102916 48% /
A /dev/sda1 ext4 10188088 4544604 5102916 48% /
A /dev/sda1 ext4 10188088 4544604 5102916 48% /var/lib/docker/aufs
A Processes running on the VM:
A top - 22:36:35 up 0 min, 0 users, load average: 0.48, 0.13, 0.04
A Tasks: 95 total, 1 running, 94 sleeping, 0 stopped, 0 zombie
A %Cpu(s): 2.1 us, 3.1 sy, 0.0 ni, 85.6 id, 9.1 wa, 0.0 hi, 0.0 si, 0.0 st
A KiB Mem: 8197596 total, 287356 used, 7910240 free, 15352 buffers
A KiB Swap: 0 total, 0 used, 0 free, 120448 cached
A {"textPayload":"","insertId":"5kdt4ig2zxfdi3","resource":{"type":"gae_app","labels":{"module_id":"default","project_id":"onkho-web-app-live","version_id":"30-1"}},"timestamp":"2018-02-28T22:36:35.183183937Z","labels":{"compute.googleapis.com/resource_type":"instance","compute.googleapis.com/resource…
George (Cloud Platform Support)
Mar 3, 2018, 3:35:00 PM3/3/18
to Google App Engine
Hi Karl,
In your initial post on this thread, you wrote that you "experienced delays in deploying our PHP flexible app whereby "gcloud deploy" times-out waiting for the new instance to start". A proper start-up process is essential to instance management. You also mention making use of PHP extensions not on the list of the extensions implemented for the app engine. What is the output of the gcloud app deploy command with the --verbosity debug parameter? This is significant when the deployment actually fails, so more insight may be gained in the reasons of failure.
For coding-related issues, stackoverflow or similar forums offer the important advantage of getting you replies from expert programmers.
Karl Tinawi
Mar 9, 2018, 7:44:37 AM3/9/18
to Google App Engine
Hi George,
Yes that's correct - I mentioned both issues as they were (in my view) related somewhat.
The relevant snipped in the log file pertaining to the timed-out deployment is below (following successful build):
2018-02-27 23:12:20,489 DEBUG root Received operation: [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542]2018-02-27 23:12:20,489 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:20,490 INFO ___FILE_ONLY___ Updating service [default] (this may take several minutes)...2018-02-27 23:12:21,669 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:27,827 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:33,253 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:39,161 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:44,540 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:50,597 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:12:56,205 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:02,243 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:07,426 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:12,910 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:18,292 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:24,153 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:29,641 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:35,097 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:41,127 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:47,087 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:52,316 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:13:58,013 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:03,792 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:09,905 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:15,471 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:21,112 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:27,082 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:32,376 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:38,369 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:44,091 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:49,423 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:14:55,468 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:00,775 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:06,669 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:12,318 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:17,672 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:22,901 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:28,599 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:34,520 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:40,532 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:46,130 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:51,964 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:15:57,935 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:03,752 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:09,361 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:15,323 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:20,783 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:26,143 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:31,957 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:37,380 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:43,312 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:49,063 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:16:55,010 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.
2018-02-27 23:17:00,907 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:06,446 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:11,842 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:17,097 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:23,039 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:28,458 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:34,363 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:40,623 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:46,405 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:51,717 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:17:57,410 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:02,891 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:08,478 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:13,838 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:19,063 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:24,489 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:29,919 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:36,086 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:41,708 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:47,712 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:53,435 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:18:59,040 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:04,339 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:10,190 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:16,118 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:22,266 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:28,166 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:34,012 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:39,325 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:45,022 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:50,668 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:19:56,417 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:02,011 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:08,047 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:13,417 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:19,657 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:25,190 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:31,112 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:37,078 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:42,549 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:48,145 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:54,017 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:20:59,950 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:05,856 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:11,471 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:17,635 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:23,520 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:29,313 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:35,395 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:41,236 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:46,963 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:52,770 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:21:58,571 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:04,473 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:10,337 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:16,270 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:22,117 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:28,240 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:33,877 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:39,587 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:45,639 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:50,801 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:22:56,562 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:01,931 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:08,089 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:13,903 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:19,752 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:25,543 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:31,611 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:36,861 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:42,185 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.
2018-02-27 23:23:47,666 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:53,787 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:23:59,383 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:04,860 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:10,503 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:15,872 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:21,134 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:27,085 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:32,437 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:38,316 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:44,152 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:49,866 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:24:55,286 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:01,063 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:06,555 INFO oauth2client.transport Refreshing due to a 401 (attempt 1/2)2018-02-27 23:25:06,558 INFO oauth2client.client Refreshing access_token2018-02-27 23:25:07,012 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:12,438 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:17,832 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:23,813 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:29,577 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:35,395 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:41,036 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:46,967 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:52,434 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:25:58,297 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:04,128 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:10,154 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:15,768 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:20,956 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:26,992 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:32,247 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:37,696 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:42,997 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:48,851 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:54,329 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:26:59,667 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:05,212 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:11,361 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:16,664 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:22,265 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:28,282 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:33,609 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:39,085 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:44,672 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:50,030 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:27:55,425 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:01,528 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:06,794 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:12,105 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:17,419 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:22,710 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:28,850 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:34,687 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:40,154 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:46,268 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:51,962 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:28:57,233 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:03,017 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:08,311 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:14,167 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:19,415 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:25,389 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:30,805 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:36,666 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:41,879 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:47,650 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:52,884 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:29:58,908 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:04,360 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:10,239 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.
2018-02-27 23:30:15,753 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:21,478 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:27,536 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:33,043 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:38,958 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:44,826 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:50,851 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:30:56,503 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:01,954 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:07,333 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:12,511 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:18,109 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:24,125 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:29,991 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:35,441 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:41,271 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:47,329 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:53,459 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:31:59,260 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:04,781 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:10,426 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:15,934 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:21,192 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:27,348 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:32,637 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:38,404 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:44,467 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:50,259 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:32:56,169 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:01,536 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:07,246 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:12,493 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:17,764 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:23,491 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:29,386 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:34,746 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:40,319 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:45,612 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:51,579 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:33:57,747 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:03,906 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:09,787 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:15,724 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:21,136 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:26,531 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:32,343 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:38,118 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:44,138 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:49,574 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:34:55,434 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:01,057 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:06,315 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:11,750 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:17,658 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:23,659 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:29,131 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:34,851 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:40,208 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:46,051 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:52,168 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:35:57,369 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:02,614 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:07,954 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:13,654 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:18,941 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:24,856 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:30,255 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:35,516 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:41,328 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:47,301 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:36:53,135 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.
2018-02-27 23:36:59,124 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:05,131 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:10,500 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:15,840 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:21,959 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:27,368 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:32,746 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:38,548 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:43,733 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:49,713 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:37:55,481 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:01,468 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:07,246 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:13,340 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:18,761 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:24,588 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:30,625 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:36,718 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:41,928 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:47,161 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:52,753 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:38:58,798 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:04,040 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:09,507 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:14,775 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:20,841 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:26,202 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:31,676 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:37,269 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:43,430 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:48,742 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:54,695 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:39:59,969 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:05,171 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:11,321 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:16,693 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:22,068 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:28,024 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:33,773 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:39,272 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:44,544 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:50,174 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:40:55,968 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:01,923 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:07,802 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:13,917 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:19,968 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:26,106 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:31,554 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:37,274 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:43,285 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:49,062 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:54,429 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:41:59,886 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:42:06,039 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:42:12,026 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:42:18,021 DEBUG root Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] not complete. Waiting to retry.2018-02-27 23:42:18,813 DEBUG root (gcloud.app.deploy) Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] timed out. This operation may still be underway.
Traceback (most recent call last): File "/usr/lib/google-cloud-sdk/lib/googlecloudsdk/calliope/cli.py", line 797, in Execute resources = calliope_command.Run(cli=self, args=args) File "/usr/lib/google-cloud-sdk/lib/googlecloudsdk/calliope/backend.py", line 757, in Run resources = command_instance.Run(args) File "/usr/lib/google-cloud-sdk/lib/surface/app/deploy.py", line 79, in Run parallel_build=False) File "/usr/lib/google-cloud-sdk/lib/googlecloudsdk/command_lib/app/deploy_util.py", line 588, in RunDeploy flex_image_build_option=flex_image_build_option) File "/usr/lib/google-cloud-sdk/lib/googlecloudsdk/command_lib/app/deploy_util.py", line 394, in Deploy extra_config_settings) File "/usr/lib/google-cloud-sdk/lib/googlecloudsdk/api_lib/app/appengine_api_client.py", line 187, in DeployService message=message) File "/usr/lib/google-cloud-sdk/lib/googlecloudsdk/api_lib/app/operations_util.py", line 250, in WaitForOperationOperationTimeoutError: Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] timed out. This operation may still be underway.2018-02-27 23:42:18,820 ERROR root (gcloud.app.deploy) Operation [apps/onkho-web-app-live/operations/550b30eb-403c-411a-999b-fa1599657542] timed out. This operation may still be underway.These logs that I see locally coincide with the previous log snippets that I obtained from the VM instance on Stackdriver. The reason the operation failed is because the VM failed to boot.
Note: Deployments did sometimes work (same docker image). It was indeed very hit-and-miss.
The reason I suggest the two issues are related is because when the VM was shutdown due to apaprent maintenance on Monday 26th Feb (I still don't know why?) it failed to boot up again. It failed to boot because of the same error error message previously posted above that I obtained from StackDriver. This is where I saw the 'perpetual reboot' cycle. Unlike the deployment that eventually times out, the unexpected reboot on Monday 26th Feb continued in this cycle until I shut it down and deleted the instance and started it again manually. In the meantime of course I had to boot up a previous instance of the app to minimise downtime.
Hope that helps - I apologise if I'm not explaining this clearly?
Thanks,
Karl
Karl Tinawi
Mar 9, 2018, 7:47:37 AM3/9/18
to Google App Engine
I must add that after using the updated / revised healthcheck configuration in our yaml files we have not experienced the same issues in deployment.
This tells me that behaviour has changed outside of our application with undesired consequences.
Thanks,
Karl
George (Cloud Platform Support)
Mar 9, 2018, 9:42:54 AM3/9/18
to Google App Engine
From the logging information provided, one is forced to conclude that your app does not start properly, which attracts failures at health checks. It is recommendable to thoroughly revise your code and identify the original cause of start up failures.
As previously mentioned, for coding-related issues, stackoverflow or similar forums offer the important advantage of getting you replies from expert programmers.
Karl Tinawi
Mar 9, 2018, 11:14:08 AM3/9/18
to Google App Engine
Hi George,
No. I don't agree that this is a valid conclusion without any investigation.
It's not the app that does not start properly, it's the VM that does not boot (!) Unless I'm missing something here?
The very first log entry in StackDriver as stated above is:
A The instance aef-default-29--1-k42h with Debian based image was created for version 29-1
A ====== Unexpected error during VM startup ======
At this point no app code has been executed. The first line "The instance .... was created for version ..." is what is logged when one clicks 'Start' on a stopped GAE instance. The VM dies immediately afterwards; this is not a code issue.
Not only was this behaviour intermittent, but to find that changing to the "new health checks" without changing any code resolved the issue instantly requires further explanation please. I don't accept that you continue to blame the code.
Please may I request once again that you look at the aforementioned issue of the VM being shutdown on Monday 26th Feb at ~06:12 due to maintenance without being live migrated first? We need to understand if this is "normal" behaviour or not.
George (Cloud Platform Support)
Mar 9, 2018, 3:22:55 PM3/9/18
to Google App Engine
You assume that we have more access rights and somehow able to see more logs or other relevant information. This is not the case, and our investigation is based on the same logging that is accessible to you. This applies to the VM being shutdown on Monday 26th Feb at ~06:12 due to maintenance as well.
When you deploy to the flexible environment, you define an image and configure it, before installing the app, so you control all deployment steps, in practice.
Reply all
Reply to author
Forward
0 new messages