Argo-cd: AutoSync doesn't work anymore

Created on 22 Sep 2019  路  31Comments  路  Source: argoproj/argo-cd

Describe the bug

When I change my bootstrap-application in git it doesn't get synced anymore to kuberntes, although AutoSync in argocd is enabled. Only when I click 'Refresh' in argocd webconsole, the application gets OutOfSync and Sync process starts.

To Reproduce

  1. change something in the git-repo of my bootstrap-application
  2. wait the AutoSync interval of 3 minutes, nothing happens (also waited for an hour)
  3. clicked 'refresh' in the webconsole of argocd for this application
  4. application gets OutOfSync and starts synchronization process

Example

I am not able to create an example, because it is vey specific to our environment. However, maybe I can narrow down to a basic example. Right now I do not know if that happens with every application in our environment or just with our boostrap-application.

Expected behavior

AutoSync should sync the application without any user interaction.

Screenshots

-

Version

1.2.0

Logs

logs from application-controller, when git-repo and kubernetes is already out-of-sync, but argocd doesn't recognize it (since we have lots of applications defined, I tried to filter a little bit for the bootstrap-application):

time="2019-09-22T09:41:12Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
W0922 09:41:12.393879       1 listers.go:77] can not retrieve list of objects using index : Index with name namespace does not exist
time="2019-09-22T09:41:12Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: argocd)" application=bootstrap-application
time="2019-09-22T09:41:12Z" level=info msg="Skipping auto-sync: application status is Synced" application=bootstrap-application
time="2019-09-22T09:41:12Z" level=info msg="Update successful" application=bootstrap-application
time="2019-09-22T09:41:12Z" level=info msg="Reconciliation completed" application=bootstrap-application fields.level=1 time_ms=281.376147
time="2019-09-22T09:41:12Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
W0922 09:41:12.674738       1 listers.go:77] can not retrieve list of objects using index : Index with name namespace does not exist
time="2019-09-22T09:41:12Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: argocd)" application=bootstrap-application
time="2019-09-22T09:41:12Z" level=info msg="Skipping auto-sync: application status is Synced" application=bootstrap-application
time="2019-09-22T09:41:12Z" level=info msg="Update successful" application=bootstrap-application
time="2019-09-22T09:41:12Z" level=info msg="Reconciliation completed" application=bootstrap-application fields.level=1 t

log when I click Refresh:

time="2019-09-22T09:43:57Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: argocd)" application=bootstrap-application
time="2019-09-22T09:43:57Z" level=info msg="copying credentials" credUrl="https://gitlab.e-bk.m086/" repoURL="https://gitlab.e-bk.m086/arz-container-plattform/k8s-platform.git"
time="2019-09-22T09:43:58Z" level=info msg="Initiated automated sync to 'd1ac81ea342f68997be69ff2befbf2b0ec1b045f'" application=bootstrap-application dest-namespace=argocd dest-server="https://kubernetes.default.svc" reason=OperationStarted type=Normal
time="2019-09-22T09:43:58Z" level=info msg="Initiated automated sync to 'd1ac81ea342f68997be69ff2befbf2b0ec1b045f'" application=bootstrap-application
time="2019-09-22T09:43:58Z" level=info msg="Updated sync status: Synced -> OutOfSync" application=bootstrap-application dest-namespace=argocd dest-server="https://kubernetes.default.svc" reason=ResourceUpdated type=Normal
time="2019-09-22T09:43:58Z" level=info msg="updated 'bootstrap-application' operation (phase: Running)"
time="2019-09-22T09:43:58Z" level=info msg="Initialized new operation: {&SyncOperation{Revision:d1ac81ea342f68997be69ff2befbf2b0ec1b045f,Prune:true,DryRun:false,SyncStrategy:nil,Resources:[],Source:nil,Manifests:[],}}" application=bootstrap-application
time="2019-09-22T09:43:58Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: argocd)" application=bootstrap-application
time="2019-09-22T09:43:58Z" level=info msg="copying credentials" credUrl="https://gitlab.e-bk.m086/" repoURL="https://gitlab.e-bk.m086/arz-container-plattform/k8s-platform.git"
time="2019-09-22T09:43:58Z" level=info msg="Update successful" application=bootstrap-application
bug

Most helpful comment

We've just upgraded to 1.2.4 and sadly didn't fix the issue where the change in the git repo isn't picked up. I'm short on time right now to debug it but probably around the 1.3 release I can really sit down and do some tests.

All 31 comments

Now I found out that for other applications AutoSync works perfectly. So I am afraid it is just with my bootstrap-application. Is there any way how to troubleshoot that further?

I looked at the controller logs again and I found that for every application I see entries like this in the log:

time="2019-09-22T10:08:11Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-22 10:05:11 +0000 UTC, expiry: 3m0s), level (2)" application=my-application

but not for the bootstrap-application. However, also the bootsra-application has this options:


  syncPolicy:
    automated:
      prune: true
      selfHeal: true

After restarting the argocd application controller the refreshing app status for the bootstrap-application appears again. I will analyze further.

I think I encountered the same problem recently. I don't know the size of your boostrap application, but what happened with us is that rendering the manifest in argocd-repo-server took longer than the default timeout (60s) and therefore application controller wasn't able to detect a change.

Try to increase --repo-server-timeout-seconds and see if this helps

thanks @amarrella . I don't know the exact reason for my problem. After restarting the application controller everything works fine. Could be that it got in some error situation after I experimented around due to https://github.com/argoproj/argo-cd/issues/2257 . But thanks for the tip with the timeout! looks very useful!

Nevermind, this still seems broken in our case :(

I'm not sure on the root cause yet.
The only warning i see is:

time="2019-09-23T10:10:20Z" level=warning msg="Could not unmarshal to object of type /v1, Kind=Secret: illegal base64 data at input byte 8"

but i don't think it's related

hm .. after restarting the controller it worked for a while in our case. But today I again find some long intervals between each refresh for the bootstrap-application, as you can see from the logs. Any help how to narrow down this problem?

kubectl logs argocd-application-controller-5987ddbf7f-xfdn8 -n argocd --since=24h | grep expire | grep bootstrap
[...]
time="2019-09-23T00:21:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:18:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:24:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:21:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:27:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:24:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:33:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:30:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:36:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:33:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:39:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:36:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:45:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:42:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T00:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 00:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:06:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:03:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:12:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:09:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:15:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:12:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:18:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:15:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:27:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:24:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:30:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:27:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:33:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:30:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:39:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:36:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:42:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:39:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:54:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:51:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T01:57:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 01:54:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:09:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:06:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:21:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:18:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:24:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:21:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:33:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:30:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:36:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:33:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:39:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:36:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:45:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:42:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:51:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:48:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T02:54:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 02:51:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:12:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:09:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:15:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:12:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:24:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:21:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:39:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:36:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:42:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:39:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T03:57:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 03:54:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T04:33:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 04:30:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T04:36:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 04:33:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T04:39:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 04:36:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T04:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 04:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T04:57:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 04:54:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T05:24:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 05:21:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T05:27:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 05:24:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T05:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 05:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T05:51:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 05:48:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T05:54:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 05:51:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T05:57:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 05:54:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T06:06:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 06:03:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T06:33:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 06:30:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T06:42:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 06:39:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T06:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 06:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T06:51:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 06:48:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T07:03:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 07:00:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T07:27:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 07:24:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T07:54:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 07:51:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T08:30:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 08:27:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T08:39:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 08:36:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T08:45:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 08:42:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T08:48:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 08:45:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T09:18:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 09:15:51 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application
time="2019-09-23T10:36:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 10:30:54 +0000 UTC, expiry: 3m0s), level (2)" application=bootstrap-application

is the secret encoded properly? can you echo "value" | base64 -d/D on it? maybe there is a blank space after the secret

@rosscdh i don't think the secret issue is related, seems to be due to https://github.com/argoproj/argo-cd/issues/2206 which i think the fix didn't make it into 1.2.1

I am von 1.2.0 and also have this problem .. but maybe we have different problems ..

I analyzed the application controller logs again. What is quiet interesting is the following. For the bootstrap-application the 'refreshing app status' always logs "level (1)":

kubectl logs argocd-application-controller-5987ddbf7f-xfdn8 -n argocd --since=30m | grep "Refreshing app status" | grep bootstrap
time="2019-09-23T12:51:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T12:51:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T12:54:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T12:54:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T12:57:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T12:57:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:00:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:00:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:03:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:03:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:06:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:06:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:09:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:09:53Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:12:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:12:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:15:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:15:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:15:56Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:15:56Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:15:57Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:16:26Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:16:26Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:18:51Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:18:52Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:20:56Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:20:56Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application
time="2019-09-23T13:21:09Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=bootstrap-application

for other applications it logs "level (2)":

kubectl logs argocd-application-controller-5987ddbf7f-xfdn8 -n argocd --since=30m | grep "Refreshing app status" | grep "i-maeve"
time="2019-09-23T12:51:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 12:48:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T12:54:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 12:51:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T12:57:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 12:54:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:00:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 12:57:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:03:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 13:00:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:06:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 13:03:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:09:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 13:06:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:12:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 13:09:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:15:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 13:12:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api
time="2019-09-23T13:18:51Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-09-23 13:15:51 +0000 UTC, expiry: 3m0s), level (2)" application=i-maeve-api

and according to https://github.com/argoproj/argo-cd/blob/release-1.2/controller/appcontroller.go#L53 this level means:

const (
    // Compare live application state against state defined in latest git revision.
    CompareWithLatest CompareWith = 2
    // Compare live application state against state defined using revision of most recent comparison.
    CompareWithRecent CompareWith = 1
    // Skip comparison and only refresh application resources tree
    ComparisonWithNothing CompareWith = 0
)

so it seems that the boostrap-application doesn't get compared to the git-repo anymore

hello @tschonnie , @amarrella . Can you please add --loglevel debug to argocd-application-controller deployment args and share logs ?

Hey @alexmt , thanks for looking into this. Here are some logs with debug, let me know if you want a more complete dump (applications is the name of my app of apps)

time="2019-09-23T14:43:53Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=applications
W0923 14:43:53.371205       1 listers.go:77] can not retrieve list of objects using index : Index with name namespace does not exist
time="2019-09-23T14:43:53Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: argocd)" application=applications
time="2019-09-23T14:43:53Z" level=debug msg="Generated config manifests" application=applications
time="2019-09-23T14:43:53Z" level=debug msg="Retrieved lived manifests" application=applications
time="2019-09-23T14:43:53Z" level=debug msg="built managed objects list" application=applications
time="2019-09-23T14:43:53Z" level=info msg="Skipping auto-sync: application status is Synced" application=applications
time="2019-09-23T14:43:53Z" level=debug msg="patch: {JSON_BLOB}" application=applications
time="2019-09-23T14:43:53Z" level=info msg="Update successful" application=applications
time="2019-09-23T14:43:53Z" level=info msg="Reconciliation completed" application=applications fields.level=1 time_ms=109.15904

these seem the relevant ones

I also got a bunch of "failed to watch" but i don't think they are relevant:

time="2019-09-23T14:44:26Z" level=debug msg="Start watch Workflow.argoproj.io on https://kubernetes.default.svc"
time="2019-09-23T14:44:32Z" level=debug msg="Failed to watch Application.argoproj.io on https://kubernetes.default.svc: Watch Application.argoproj.io on https://kubernetes.default.svc has closed, retrying in 1s"
time="2019-09-23T14:44:33Z" level=debug msg="Start watch Application.argoproj.io on https://kubernetes.default.svc"
time="2019-09-23T14:44:36Z" level=debug msg="Failed to watch TLSContext.getambassador.io on https://kubernetes.default.svc: Watch TLSContext.getambassador.io on https://kubernetes.default.svc has closed, retrying in 1s"
time="2019-09-23T14:44:37Z" level=debug msg="Start watch TLSContext.getambassador.io on https://kubernetes.default.svc"
time="2019-09-23T14:44:37Z" level=debug msg

Looks like this is a bug related to git optimization. Controller incorrectly decides to skip fetching new version from Git if application is big and target state changes frequently. This definitely deserves patch release. hope to get it today/tomorrow

Still seeing this issue,
time="2019-10-11T19:32:01Z" level=info msg="Refreshing app status (comparison expired. reconciledAt: 2019-10-11 19:29:01 +0000 UTC, expiry: 3m0s), level (2)" application=blue

was this fixed in v1.2.3 ?

The fix is in v1.2.3 . At least one more user reported that argocd misses git change. I'm trying to find a way to reproduce it. The log message from your comment actually looks good - level 2 means full reconciliation. Can you pease attach more logs from controller and repo server?

You are using auto-sync, right?

You are using auto-sync, right?

Sure.
but in my case i just removed everything and installed it again after a week of going forward and back with ARGO version and now magically no error

im implementing this in numerous enterprise clients of mine instead of spinnaker.
hopefully this wont repair as k8s and their applications are installed as a blackbox for their clients

I also encounterd this issue. I'm using ArgoCD v1.2.3 and kustomize.
In v1.2.3, has this issue completely resolved?
In my case, this sometimes occurred using CronJob, however, when trying to sync other resoueces(e.g. Deployment, Ingress), no problems did.

The fix in v1.2.3 forces argocd to check latest manifest versions every 3 mins. However, fix does not cover the case when app spec changes. PR with the fix: https://github.com/argoproj/argo-cd/pull/2543

We've just upgraded to 1.2.4 and sadly didn't fix the issue where the change in the git repo isn't picked up. I'm short on time right now to debug it but probably around the 1.3 release I can really sit down and do some tests.

Keep trying to reproduce and fix.

I am hitting this bug as well. I posted logs of my installation in the slack channel already. Maybe they help with debugging: https://argoproj.slack.com/archives/CASHNF6MS/p1571053735124500?thread_ts=1570797753.089700&cid=CASHNF6MS

@wecger logs:

reposerver:
01  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
02  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
03  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:default/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
04  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=132.562 span.kind=server system=grpc
05  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:podinfo/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
06  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=135.429 span.kind=server system=grpc
07  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
08  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-ingress-nginx/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
09  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=137.604 span.kind=server system=grpc
10  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
11  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-logging/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
12  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=167.315 span.kind=server system=grpc
13  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
14  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-sealed-secrets/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
15  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=175.393 span.kind=server system=grpc
16  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
17  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:bases/monitoring-app,TargetRevision:integration,Helm:&ApplicationSourceHelm{ValueFiles:[values.yaml ../../ct-monitoring/bases/myvalues.yaml ../../ct-monitoring/emea-nonprod-ct-1/myvalues.yaml],Parameters:[],ReleaseName:,},Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
18  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=187.102 span.kind=server system=grpc
19  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
20  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-test/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
21  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=186.969 span.kind=server system=grpc
22  time="2019-10-14T06:42:37Z" level=debug msg="revision 'integration' resolved to 'b2521fcdf431efff96537ed5bde5783ea91349fe'"
23  time="2019-10-14T06:42:37Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-app-gefahrenertest/app2,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/b2521fcdf431efff96537ed5bde5783ea91349fe"
24  time="2019-10-14T06:42:37Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:37Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:37Z" grpc.time_ms=242.65 span.kind=server system=grpc
25  time="2019-10-14T06:42:38Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-automation/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/25300db267c8582c38520f3c45ce9234c409ba3e"
26  time="2019-10-14T06:42:38Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:38Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:38Z" grpc.time_ms=2.144 span.kind=server system=grpc
27  time="2019-10-14T06:42:39Z" level=info msg="manifest cache hit: &ApplicationSource{RepoURL:https://<repodomain>/<repocontext>,Path:ct-automation/emea-nonprod-ct-1,TargetRevision:integration,Helm:nil,Kustomize:nil,Ksonnet:nil,Directory:nil,Plugin:nil,}/25300db267c8582c38520f3c45ce9234c409ba3e"
28  time="2019-10-14T06:42:39Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GenerateManifest grpc.request.deadline="2019-10-14T06:43:39Z" grpc.service=repository.RepoServerService grpc.start_time="2019-10-14T06:42:39Z" grpc.time_ms=2.171 span.kind=server system=grpc
appcontroller:
01 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=default-emea-nonprod-ct-1
02 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=podinfo-emea-nonprod-ct-1
03 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=default-emea-nonprod-ct-1
04 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=default-emea-nonprod-ct-1 dest-namespace=default dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=501.751376
05 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=podinfo-emea-nonprod-ct-1
06 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=podinfo-emea-nonprod-ct-1 dest-namespace=podinfo dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=503.044614
07 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-test-emea-nonprod-ct-1
08 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-sealed-secrets-emea-nonprod-ct-1
09 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-test-emea-nonprod-ct-1
10 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-test-emea-nonprod-ct-1 dest-namespace=ct-test dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=872.741906
11 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-app-gefahrenertest-2
12 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-ingress-nginx-emea-nonprod-ct-1
13 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-sealed-secrets-emea-nonprod-ct-1
14 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-sealed-secrets-emea-nonprod-ct-1 dest-namespace=ct-sealed-secrets dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=905.331343
15 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-ingress-nginx-emea-nonprod-ct-1
16 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-ingress-nginx-emea-nonprod-ct-1 dest-namespace=ct-ingress-nginx dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=947.438668
17 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-app-gefahrenertest-2
18 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-app-gefahrenertest-2 dest-namespace=ct-app-gefahrenertest dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=951.178932
19 time="2019-10-14T06:42:38Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=ct-app-gefahrenertest-main
20 W1014 06:42:38.634688       1 listers.go:77] can not retrieve list of objects using index : Index with name namespace does not exist
21 time="2019-10-14T06:42:38Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: ct-automation)" application=ct-app-gefahrenertest-main
22 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-globaldash-emea-nonprod-ct-1
23 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-logging-emea-nonprod-ct-1
24 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-logging-emea-nonprod-ct-1
25 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-logging-emea-nonprod-ct-1 dest-namespace=ct-logging dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=1081.572003
26 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-globaldash-emea-nonprod-ct-1
27 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-globaldash-emea-nonprod-ct-1 dest-namespace=ct-globaldash dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=1082.678705
28 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-app-gefahrenertest-main
29 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-monitoring-emea-nonprod-ct-1
30 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-app-gefahrenertest-main
31 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-app-gefahrenertest-main dest-namespace=ct-automation dest-server="https://kubernetes.default.svc" fields.level=1 time_ms=117.984805
32 time="2019-10-14T06:42:38Z" level=info msg="Update successful" application=ct-monitoring-emea-nonprod-ct-1
33 time="2019-10-14T06:42:38Z" level=info msg="Reconciliation completed" application=ct-monitoring-emea-nonprod-ct-1 dest-namespace=ct-monitoring dest-server="https://kubernetes.default.svc" fields.level=2 time_ms=1142.708732
34 time="2019-10-14T06:42:38Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-automation-emea-nonprod-ct-1
35 time="2019-10-14T06:42:38Z" level=info msg="Updated health status: Progressing -> Healthy" application=ct-automation-emea-nonprod-ct-1 dest-namespace=ct-automation dest-server="https://kubernetes.default.svc" reason=ResourceUpdated type=Normal
36 time="2019-10-14T06:42:39Z" level=info msg="Update successful" application=ct-automation-emea-nonprod-ct-1
37 time="2019-10-14T06:42:39Z" level=info msg="Reconciliation completed" application=ct-automation-emea-nonprod-ct-1 dest-namespace=ct-automation dest-server="https://kubernetes.default.svc" fields.level=1 time_ms=1024.491094
38 time="2019-10-14T06:42:39Z" level=info msg="Refreshing app status (controller refresh requested), level (1)" application=ct-automation-emea-nonprod-ct-1
39 W1014 06:42:39.057953       1 listers.go:77] can not retrieve list of objects using index : Index with name namespace does not exist
40 time="2019-10-14T06:42:39Z" level=info msg="Comparing app state (cluster: https://kubernetes.default.svc, namespace: ct-automation)" application=ct-automation-emea-nonprod-ct-1
41 time="2019-10-14T06:42:39Z" level=info msg="Skipping auto-sync: application status is Synced" application=ct-automation-emea-nonprod-ct-1
42 time="2019-10-14T06:42:39Z" level=info msg="Updated health status: Progressing -> Healthy" application=ct-automation-emea-nonprod-ct-1 dest-namespace=ct-automation dest-server="https://kubernetes.default.svc" reason=ResourceUpdated type=Normal
43 time="2019-10-14T06:42:39Z" level=info msg="Update successful" application=ct-automation-emea-nonprod-ct-1
44 time="2019-10-14T06:42:39Z" level=info msg="Reconciliation completed" application=ct-automation-emea-nonprod-ct-1 dest-namespace=ct-automation dest-server="https://kubernetes.default.svc" fields.level=1 time_ms=355.30549299999996

Finally found the real reason ( at least I'm 99% sure about it :) ) . The controller incorrectly updates the state.reconciledAt field even if app reconciliation was performed using cached manifests.

PR is in review: https://github.com/argoproj/argo-cd/pull/2581

Will create v1.2.5 once it is merged.

Keeping the issue open until getting confirmation that the bug is fixed.

Release v1.2.5 is available https://github.com/argoproj/argo-cd/releases/tag/v1.2.5 . Please give it a try.

This fixes the problem for me. I vote to close this issue.

This fixes it for us too. Thanks!

It seems to be fixed here too.

confirmed from my side as well. Thanks a lot and keep up your great work!

Please re-open if not fixed.

Was this page helpful?
0 / 5 - 0 ratings

Related issues

storm1kk picture storm1kk  路  20Comments

gregdurham picture gregdurham  路  27Comments

phillebaba picture phillebaba  路  23Comments

cchanley2003 picture cchanley2003  路  25Comments

raffaelespazzoli picture raffaelespazzoli  路  21Comments