ERROR juju.worker.caasapplicationprovisioner.runner exited "<application>": restart immediately

[Junien F]

Hello,

Using juju 2.9.0 with microk8s v1.20.7 (snap).

Whenever I deploy a new app, I see the following in "juju debug-log" :

$ juju debug-log &
[1] 1234
$ juju deploy ./gunicorn-k8s.charm app3 --resource gunicorn-image='gunicorncharmers/gunicorn-app:20.0.4-20.04_edge'
controller-0: 18:24:27 ERROR juju.worker.caasapplicationprovisioner.runner exited "app3": restart immediately

But the deploy continues properly. Could we please fix whatever is causing this spurious error message ?

Thanks

[John A Meinel (jameinel)]

Do you have additional context on the logging to identify why we feel we need to restart the app? I would guess there is more context than just the final step that caused the worker to restart.

[Junien F (axino)]

I'm not sure how much more I can provide :

$ juju add-model dev
Added 'dev' model on microk8s/localhost with credential 'microk8s' for user 'admin'

$ juju model-config logging-config="<root>=WARNING;unit=DEBUG"

$ juju debug-log &
[1] 22334

controller-0: 22:40:07 INFO juju.worker.apicaller [8e6bca] "controller-0" successfully connected to "localhost:17070"
controller-0: 22:40:07 INFO juju.worker.logforwarder config change - log forwarding not enabled
controller-0: 22:40:07 INFO juju.worker.logger logger worker started
controller-0: 22:40:07 INFO juju.worker.pruner.action status history config: max age: 336h0m0s, max collection size 5120M for dev (8e6bcabe-421f-41ba-8729-30a64974d052)
controller-0: 22:40:07 INFO juju.worker.pruner.statushistory status history config: max age: 336h0m0s, max collection size 5120M for dev (8e6bcabe-421f-41ba-8729-30a64974d052)

$ juju deploy ./gunicorn-k8s.charm app3 --resource gunicorn-image='gunicorncharmers/gunicorn-app:20.0.4-20.04_edge'
Located local charm "gunicorn-k8s", revision 0
Deploying "app3" from local charm "gunicorn-k8s", revision 0

controller-0: 22:40:39 ERROR juju.worker.caasapplicationprovisioner.runner exited "app3": restart immediately
controller-0: 22:40:47 ERROR juju.worker.caasapplicationprovisioner.runner exited "app3": Operation cannot be fulfilled on pods "app3-0": the object has been modified; please apply your changes to the latest version and try again
unit-app3-0: 22:41:00 DEBUG unit.app3/0.juju-log Operator Framework 1.0.dev0+unknown up and running.
unit-app3-0: 22:41:00 INFO unit.app3/0.juju-log Running legacy hooks/install.
unit-app3-0: 22:41:00 DEBUG unit.app3/0.juju-log Operator Framework 1.0.dev0+unknown up and running.
unit-app3-0: 22:41:00 DEBUG unit.app3/0.juju-log Charm called itself via hooks/install.
unit-app3-0: 22:41:00 DEBUG unit.app3/0.juju-log Legacy hooks/install exited with status 0.
[.. etc deployment continues ...]

[Junien F (axino)]

Sometimes I get ore than one restart (again, this is on a fresh model) :

controller-0: 22:50:59 INFO juju.worker.apicaller [947f86] "controller-0" successfully connected to "localhost:17070"
controller-0: 22:50:59 INFO juju.worker.logforwarder config change - log forwarding not enabled
controller-0: 22:50:59 INFO juju.worker.logger logger worker started
controller-0: 22:50:59 INFO juju.worker.pruner.statushistory status history config: max age: 336h0m0s, max collection size 5120M for dev2 (947f8629-d5b5-40e6-8bbd-9ad4098c2bbb)
controller-0: 22:50:59 INFO juju.worker.pruner.action status history config: max age: 336h0m0s, max collection size 5120M for dev2 (947f8629-d5b5-40e6-8bbd-9ad4098c2bbb)
controller-0: 22:51:31 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately
controller-0: 22:51:34 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately
controller-0: 22:51:37 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately
controller-0: 22:51:40 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately
controller-0: 22:51:47 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": Operation cannot be fulfilled on pods "app-0": the object has been modified; please apply your changes to the latest version and try again
unit-app-0: 22:51:50 DEBUG unit.app/0.juju-log Operator Framework 1.0.dev0+unknown up and running.
unit-app-0: 22:51:50 INFO unit.app/0.juju-log Running legacy hooks/install.

[Ian Booth (wallyworld)]

Can you provide a link to the charm source code? Looks like you are deploying a local charm?

[Tom Haddon (mthaddon)]

The charm code can be found at https://code.launchpad.net/~axino/charm-k8s-gunicorn/+git/charm-k8s-gunicorn/+ref/sidecar

[Junien F (axino)]

The charm is now pushed on the "edge" channel. I was able to repro on a fresh controller, ie :

$ sudo snap install microk8s --classic
$ microk8s enable storage dns registry ingress
$ juju bootstrap microk8s micro
$ juju add-model dev
$ juju model-config logging-config="<root>=WARNING;unit=DEBUG"

And then :

$ juju deploy gunicorn-k8s --channel edge app

I don't always get this error though. Also sometimes I get :

controller-0: 20:53:42 ERROR juju.worker.caasapplicationprovisioner.runner exited "app3": Operation cannot be fulfilled on pods "app3-0": the object has been modified; please apply your changes to the latest version and try again

I was able to repro with <root>=DEBUG :

$ juju deploy gunicorn-k8s --channel edge app6
Located charm "gunicorn-k8s" in charm-hub, revision 3
Deploying "app6" from charm-hub charm "gunicorn-k8s", revision 3 in channel edge

controller-0: 20:56:15 DEBUG juju.worker.caasapplicationprovisioner.runner start "app6"
controller-0: 20:56:15 INFO juju.worker.caasapplicationprovisioner.runner start "app6"
controller-0: 20:56:15 DEBUG juju.worker.caasapplicationprovisioner.runner "app6" started
controller-0: 20:56:15 DEBUG juju.worker.storageprovisioner filesystems alive: [], dying: [], dead: []
controller-0: 20:56:15 DEBUG juju.worker.storageprovisioner filesystem attachment alive: [], dying: [], dead: []
controller-0: 20:56:15 DEBUG juju.worker.storageprovisioner volume attachments alive: [], dying: [], dead: []
controller-0: 20:56:15 DEBUG juju.worker.caasapplicationprovisioner.applicationworker updating application "app6" scale to 1
controller-0: 20:56:15 INFO juju.worker.caasapplicationprovisioner.runner stopped "app6", err: restart immediately
controller-0: 20:56:15 DEBUG juju.worker.caasapplicationprovisioner.runner "app6" done: restart immediately
controller-0: 20:56:15 ERROR juju.worker.caasapplicationprovisioner.runner exited "app6": restart immediately
controller-0: 20:56:15 INFO juju.worker.caasapplicationprovisioner.runner restarting "app6" in 3s

[Ian Booth (wallyworld)]

I just tried this on the tip of 2.9 (which will become juju 2.9.3 in the next day or so) and it worked without issue. It also worked on juju 2.9.2 from the 2.9/candidate channel.

I retested using juju 2.9.0 and sure enough, saw the same errors.

So this appears fixed in 2.9.2 onwards. Can you confirm it's ok for you using 2.9/candidate?

[Tom Haddon (mthaddon)]

I'm still seeing this on 2.9.4:

controller-0: 11:41:02 INFO juju.worker.apicaller [bb5057] "controller-0" successfully connected to "localhost:17070"
controller-0: 11:41:02 INFO juju.worker.logforwarder config change - log forwarding not enabled
controller-0: 11:41:02 INFO juju.worker.logger logger worker started
controller-0: 11:41:02 INFO juju.worker.pruner.statushistory status history config: max age: 336h0m0s, max collection size 5120M for dev (bb50575c-fe96-4713-888b-9700a2f35b46)
controller-0: 11:41:02 INFO juju.worker.pruner.action status history config: max age: 336h0m0s, max collection size 5120M for dev (bb50575c-fe96-4713-888b-9700a2f35b46)
controller-0: 11:41:44 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately
controller-0: 11:41:47 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately
controller-0: 11:41:50 ERROR juju.worker.caasapplicationprovisioner.runner exited "app": restart immediately

$ juju status
Model Controller Cloud/Region Version SLA Timestamp
dev microk8s-localhost microk8s/localhost 2.9.4 unsupported 11:43:58+02:00

App Version Status Scale Charm Store Channel Rev OS Address Message
app maintenance 1 gunicorn-k8s charmhub edge 3 kubernetes waiting for pebble to start

Unit Workload Agent Address Ports Message
app/0* maintenance idle 10.1.234.59 waiting for pebble to start

[John A Meinel (jameinel)]

Is this still an issue in 2.9.12? Offhand it looks like it might be something getting an error from the underlying K8s which is why we are unable to reproduce it. We should certainly be logging more of an error if this is occurring.

[Tom Haddon (mthaddon)]

I think this can be closed. I've just tried it again on 2.9.14 (in microk8s) in three different circumstances:

1) A fresh deploy of gunicorn-k8s in an existing microk8s
2) A second deploy of gunicorn-k8s with the image cached
3) A fresh deploy of gunicorn-k8s in a newly provisioned microk8s instance

In all cases I didn't see the log messages above.

[Canonical Juju QA Bot (juju-qa-bot)]

This Medium-priority bug has not been updated in 60 days, so we're marking it Low importance. If you believe this is incorrect, please update the importance.