Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Multiple empty commits since flux2 v0.37 #466

Closed
srgvg opened this issue Nov 29, 2022 · 26 comments · Fixed by #470
Closed

Multiple empty commits since flux2 v0.37 #466

srgvg opened this issue Nov 29, 2022 · 26 comments · Fixed by #470
Assignees
@pjbgf
Labels
area/git Git related issues and pull requests bug Something isn't working
Milestone
GA

Comments

@srgvg
Copy link

srgvg commented Nov 29, 2022

Initially discussed in slack

➞  flux version
flux: v0.37.0
helm-controller: v0.21.0
kustomize-controller: v0.25.0
notification-controller: v0.23.5
source-controller: v0.24.4

This started after upgrading to 0.37:

Date:   Fri Nov 25 00:33:30 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

I get such a commit like every 5s

At some point, restarting the image-automation controller stopped that, however some time later it had restarted again. I think I experienced that twice, however not realising exactly enough what was happening, I didn't keep any logs from this controller, unfortunately.

This is the same base git repo that flux kustomize uses, happens on the master branch, hosted in Gitlab. Verified there were no commits in the container image gerenrating git commit that would have warranted any update. The latest actual image version, gitlab pipeline and latest git commit are all related, and several days older than aforementioned flux2 upgrade. All git authentication happens through an SSH keypair.

Relevant automation manifests:

apiVersion: v1
items:
- apiVersion: image.toolkit.fluxcd.io/v1beta1
  kind: ImagePolicy
  metadata:
    labels:
      kustomize.toolkit.fluxcd.io/name: mycompany-www-dev
      kustomize.toolkit.fluxcd.io/namespace: flux-system
    name: mycompany-www-dev
    namespace: flux-system
  spec:
    filterTags:
      extract: $datetime
      pattern: ^(?P<datetime>[0-9]{6}.[0-9]{6})-(?P<hash>[a-fA-F0-9]{8})-dev
    imageRepositoryRef:
      name: mycompany-www-dev
    policy:
      numerical:
        order: asc
- apiVersion: image.toolkit.fluxcd.io/v1beta1
  kind: ImagePolicy
  metadata:
    labels:
      kustomize.toolkit.fluxcd.io/name: mycompany-www-prod
      kustomize.toolkit.fluxcd.io/namespace: flux-system
    name: mycompany-www-prod
    namespace: flux-system
  spec:
    filterTags:
      extract: $datetime
      pattern: ^(?P<datetime>[0-9]{6}.[0-9]{6})-(?P<hash>[a-fA-F0-9]{8})-prod
    imageRepositoryRef:
      name: mycompany-www-prod
    policy:
      numerical:
        order: asc
- apiVersion: image.toolkit.fluxcd.io/v1beta1
  kind: ImageRepository
  metadata:
    labels:
      kustomize.toolkit.fluxcd.io/name: mycompany-www-dev
      kustomize.toolkit.fluxcd.io/namespace: flux-system
    name: mycompany-www-dev
    namespace: flux-system
  spec:
    image: registry.gitlab.com/mycompany/infra/website
    interval: 2m30s
    secretRef:
      name: gitlab-mycompany-registry
- apiVersion: image.toolkit.fluxcd.io/v1beta1
  kind: ImageRepository
  metadata:
    labels:
      kustomize.toolkit.fluxcd.io/name: mycompany-www-prod
      kustomize.toolkit.fluxcd.io/namespace: flux-system
    name: mycompany-www-prod
    namespace: flux-system
  spec:
    image: registry.gitlab.com/mycompany/infra/website
    interval: 2m30s
    secretRef:
      name: gitlab-mycompany-registry
kind: List
metadata:
  resourceVersion: ""

example of a correct commit

commit 8ea
Author: fluxcdbot <fluxcdbot@users.noreply.github.com>
Date:   Sun May 22 11:54:53 2022 +0000

    registry.gitlab.com/mycompany/infra/website:32cc3e24-1653220443

diff --git deploy/overlays/development/deployment.yaml deploy/overlays/development/deployment.yaml
index 68c962e..70bc2d3 100644
--- deploy/overlays/development/deployment.yaml
+++ deploy/overlays/development/deployment.yaml
@@ -7,4 +7,4 @@ spec:
     spec:
       containers:
         - name: mycompany-website
-          image: registry.gitlab.com/mycompany/infra/website:32cc3e24-1653167652 # {"$imagepolicy": "flux-system:mycompany-website-dev"}
+          image: registry.gitlab.com/mycompany/infra/website:32cc3e24-1653220443 # {"$imagepolicy": "flux-system:mycompany-website-dev"}

I will monitor this more closely, and get back here with more info, and hopefully some more relevant logs.
@pjbgf pjbgf added bug Something isn't working area/git Git related issues and pull requests labels Nov 29, 2022
@pjbgf pjbgf modified the milestones: Bootstrap GA, GA Nov 29, 2022
@pjbgf
Copy link
Member

pjbgf commented Nov 29, 2022

Thank you for reporting this @srgvg. I have been trying to reproduce this in the last hour with no luck so far.

(cc @aryan9600)

@aryan9600
Copy link
Member

hi @srgvg, could you also please share the relevant ImageUpdateAutomation objects? thanks

@srgvg
Copy link
Author

srgvg commented Nov 30, 2022 

apiVersion: image.toolkit.fluxcd.io/v1beta1
kind: ImageUpdateAutomation
metadata:
  name: flux-system
  namespace: flux-system
spec:
  git:
    checkout:
      ref:
        branch: master
    commit:
      author:
        email: fluxcd@${cluster_name}
        name: ${cluster_name//./-}
      messageTemplate: |
        Automated image update {{ .AutomationObject }}

        Images:
        {{ range .Updated.Images -}}
        - {{.}}
        {{ end -}}

        Objects:
        {{ range $resource, $_ := .Updated.Objects -}}
        - {{ $resource.Kind }} {{ $resource.Name }}
        {{ end -}}

        Files:
        {{ range $filename, $_ := .Updated.Files -}}
        - {{ $filename }}
        {{ end -}}
  interval: 2m30s
  sourceRef:
    kind: GitRepository
    name: flux-system
  update:
    path: ${cluster_path:=.}/
    strategy: Setters

@srgvg
Copy link
Author

srgvg commented Nov 30, 2022 •
edited by pjbgf
Loading

Just found out that I disabled earlier the ImageUpdateAutomation object, which was the reason this issue stopped happening. Just re-enabled it, and it does happen again now.

The image-automation-controller immediately reacts, and starts with doing 3 empty commits, the first showing up as

commit c6ab....
Author:     k0-scw-company-cloud <fluxcd@k0.scw.company.cloud>
AuthorDate: Wed Nov 30 13:17:40 2022 +0000
Commit:     k0-scw-company-cloud <fluxcd@k0.scw.company.cloud>
CommitDate: Wed Nov 30 13:17:40 2022 +0000

   Automated image update flux-system/flux-system

   Images:
   Objects:
   Files:

About 3 minutes later, it makes again 3 empty commits. Relevant logs are

All commits are identical (except commit has and datetime of course)

{"level":"info","ts":"2022-11-30T13:17:42.348Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"84c04660-437d-4cf8-8a60-509816d15018","revision":"c6ab258e35e9b8121e1c918ccafaa7d18361c6f1","branch":"master"}
{"level":"info","ts":"2022-11-30T13:17:50.463Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"9de40540-9210-4a8b-9673-b81b09b2190a","revision":"8586db7a7000ede38c747b86bc8780b66d8eba58","branch":"master"}
{"level":"info","ts":"2022-11-30T13:17:54.705Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"edf50510-028b-40ee-8411-1d49bf43323b","revision":"8d3021f448516c62c7071a3cefcfd9a51f50f89c","branch":"master"}
{"level":"info","ts":"2022-11-30T13:20:10.554Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"6d911e23-77c3-4834-8fb2-2eed38968160","revision":"8fcbf04b31dded6c4563964a9e276008452fdafa","branch":"master"}
{"level":"info","ts":"2022-11-30T13:20:14.930Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"73a70ce0-d2c5-4f47-81fc-554a4db00436","revision":"7bf58bd1470bbea403ac543c100ddfc6f735d74d","branch":"master"}
{"level":"info","ts":"2022-11-30T13:20:19.557Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"0da1c431-c9f2-4f97-b981-8a4314282933","revision":"775f2f3dea99fac0394c26ec2092ff6dbe08e39d","branch":"master"}

After that again after ~2-3 minutes. This seems to match the aforementioned interval: 2m30s.

Currently:

➞  flux get images all
NAME                           	LAST SCAN                	SUSPENDED	READY	MESSAGE
imagerepository/company-www-dev 	2022-11-30T14:22:23+01:00	False    	True 	successful scan, found 49 tags	
imagerepository/company-www-prod	2022-11-30T14:22:22+01:00	False    	True 	successful scan, found 49 tags	

NAME                       	LATEST IMAGE                                                        	READY	MESSAGE                                                                       
imagepolicy/company-www-dev 	registry.gitlab.com/company/infra/website:221107.085006-e8fe8e2a-dev 	True 	Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.085006-e8fe8e2a-dev 	
imagepolicy/company-www-prod	registry.gitlab.com/company/infra/website:221107.121258-e8fe8e2a-prod	True 	Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.121258-e8fe8e2a-prod	

NAME                             	LAST RUN                 	SUSPENDED	READY	MESSAGE
imageupdateautomation/flux-system	2022-11-30T14:22:48+01:00	False    	True 	committed and pushed 2e0d48d2c553181402bd15e1729b506b5a52783c to master

Notice those 49 tags are the same amount as before those commits (confirming no new tags were detected), the image policy mentions the latest detected tags datecoded on November 7.

In all of this setup, tehere are only 2 places with a imagepolicy tag (also as aforementioned, # {"$imagepolicy": "flux-system:......

@srgvg
Copy link
Author

srgvg commented Nov 30, 2022

I set log level to debug on both image-* controllers.

At and after restart I now get

for the image-automation-controller:

{"level":"info","ts":"2022-11-30T13:39:11.313Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-11-30T13:39:11.319Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-11-30T13:39:11.346Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
{"level":"info","ts":"2022-11-30T13:39:11.346Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
I1130 13:39:11.448427       1 leaderelection.go:248] attempting to acquire leader lease flux-system/image-automation-controller-leader-election...
I1130 13:39:21.905646       1 leaderelection.go:258] successfully acquired lease flux-system/image-automation-controller-leader-election
{"level":"info","ts":"2022-11-30T13:39:21.909Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImageUpdateAutomation"}
{"level":"info","ts":"2022-11-30T13:39:21.909Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-11-30T13:39:21.909Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-11-30T13:39:21.909Z","msg":"Starting Controller","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation"}
{"level":"debug","ts":"2022-11-30T13:39:21.903Z","logger":"events","msg":"image-automation-controller-755695966-z6tb7_98f9cd65-4ef7-42b7-abc2-5be5644a1ad8 became leader","type":"Normal","object":{"kind":"Lease","namespace":"flux-system","name":"image-automation-controller-leader-election","uid":"f9e1df7d-9f10-42d8-8cee-386df3e434de","apiVersion":"coordination.k8s.io/v1","resourceVersion":"25643911468"},"reason":"LeaderElection"}
{"level":"info","ts":"2022-11-30T13:39:22.015Z","msg":"Starting workers","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","worker count":4}
{"level":"debug","ts":"2022-11-30T13:39:22.019Z","msg":"fetching git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"e86235d4-ed9b-440c-8283-ca7fa6b5d3b3","gitrepository":{"namespace":"flux-system","name":"flux-system"}}
{"level":"debug","ts":"2022-11-30T13:39:22.020Z","msg":"attempting to clone git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"e86235d4-ed9b-440c-8283-ca7fa6b5d3b3","gitrepository":{"namespace":"flux-system","name":"flux-system"},"ref":{"branch":"master"},"working":"/tmp/flux-system-flux-system1708877852"}
{"level":"debug","ts":"2022-11-30T13:39:24.876Z","msg":"updating with setters according to image policies","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"e86235d4-ed9b-440c-8283-ca7fa6b5d3b3","count":2,"manifests-path":"/tmp/flux-system-flux-system1708877852/k8s/clusters/k0.scw.company.cloud"}
{"level":"debug","ts":"2022-11-30T13:39:24.909Z","msg":"ran updates to working dir","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"e86235d4-ed9b-440c-8283-ca7fa6b5d3b3","working":"/tmp/flux-system-flux-system1708877852"}
{"level":"info","ts":"2022-11-30T13:39:27.432Z","msg":"Committed and pushed change 5a30bfef48c570a94d1b03279907d564cce51798 to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","name":"flux-system","namespace":"flux-system","reconciler kind":"ImageUpdateAutomation","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:39:27.440Z","logger":"events","msg":"Committed and pushed change 5a30bfef48c570a94d1b03279907d564cce51798 to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","type":"Normal","object":{"kind":"ImageUpdateAutomation","namespace":"flux-system","name":"flux-system","uid":"e916aa18-6d8c-4994-8e6e-89f42c2bb980","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25643892888"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:39:27.516Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"e86235d4-ed9b-440c-8283-ca7fa6b5d3b3","revision":"5a30bfef48c570a94d1b03279907d564cce51798","branch":"master"}
{"level":"debug","ts":"2022-11-30T13:39:27.594Z","msg":"fetching git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"76333a64-6756-4bbb-bfb6-ffeb9aab9f5b","gitrepository":{"namespace":"flux-system","name":"flux-system"}}
{"level":"debug","ts":"2022-11-30T13:39:27.595Z","msg":"attempting to clone git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"76333a64-6756-4bbb-bfb6-ffeb9aab9f5b","gitrepository":{"namespace":"flux-system","name":"flux-system"},"ref":{"branch":"master"},"working":"/tmp/flux-system-flux-system3092358335"}
{"level":"debug","ts":"2022-11-30T13:39:29.985Z","msg":"updating with setters according to image policies","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"76333a64-6756-4bbb-bfb6-ffeb9aab9f5b","count":2,"manifests-path":"/tmp/flux-system-flux-system3092358335/k8s/clusters/k0.scw.company.cloud"}
{"level":"debug","ts":"2022-11-30T13:39:30.036Z","msg":"ran updates to working dir","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"76333a64-6756-4bbb-bfb6-ffeb9aab9f5b","working":"/tmp/flux-system-flux-system3092358335"}
{"level":"info","ts":"2022-11-30T13:39:32.676Z","msg":"Committed and pushed change a8ec641cd4aeb31baa9100789df236b6a7aa0f76 to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","name":"flux-system","namespace":"flux-system","reconciler kind":"ImageUpdateAutomation","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:39:32.678Z","logger":"events","msg":"Committed and pushed change a8ec641cd4aeb31baa9100789df236b6a7aa0f76 to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","type":"Normal","object":{"kind":"ImageUpdateAutomation","namespace":"flux-system","name":"flux-system","uid":"e916aa18-6d8c-4994-8e6e-89f42c2bb980","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25643913268"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:39:32.753Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"76333a64-6756-4bbb-bfb6-ffeb9aab9f5b","revision":"a8ec641cd4aeb31baa9100789df236b6a7aa0f76","branch":"master"}
{"level":"debug","ts":"2022-11-30T13:40:34.802Z","msg":"fetching git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"7333ae75-1f62-4d29-a2d7-7576f41c1ec6","gitrepository":{"namespace":"flux-system","name":"flux-system"}}
{"level":"debug","ts":"2022-11-30T13:40:34.806Z","msg":"attempting to clone git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"7333ae75-1f62-4d29-a2d7-7576f41c1ec6","gitrepository":{"namespace":"flux-system","name":"flux-system"},"ref":{"branch":"master"},"working":"/tmp/flux-system-flux-system1923795311"}
{"level":"debug","ts":"2022-11-30T13:40:38.353Z","msg":"updating with setters according to image policies","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"7333ae75-1f62-4d29-a2d7-7576f41c1ec6","count":2,"manifests-path":"/tmp/flux-system-flux-system1923795311/k8s/clusters/k0.scw.company.cloud"}
{"level":"debug","ts":"2022-11-30T13:40:38.450Z","msg":"ran updates to working dir","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"7333ae75-1f62-4d29-a2d7-7576f41c1ec6","working":"/tmp/flux-system-flux-system1923795311"}
{"level":"info","ts":"2022-11-30T13:40:42.711Z","msg":"Committed and pushed change 2415f37883f54fd643a7feba1f2b00df5522f6cd to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","name":"flux-system","namespace":"flux-system","reconciler kind":"ImageUpdateAutomation","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:40:42.723Z","logger":"events","msg":"Committed and pushed change 2415f37883f54fd643a7feba1f2b00df5522f6cd to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","type":"Normal","object":{"kind":"ImageUpdateAutomation","namespace":"flux-system","name":"flux-system","uid":"e916aa18-6d8c-4994-8e6e-89f42c2bb980","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25643914789"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:40:42.779Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"7333ae75-1f62-4d29-a2d7-7576f41c1ec6","revision":"2415f37883f54fd643a7feba1f2b00df5522f6cd","branch":"master"}

and for the image-reflector-controller:

badger 2022/11/30 13:39:23 INFO: All 0 tables opened in 0s
badger 2022/11/30 13:39:23 INFO: Discard stats nextEmptySlot: 0
badger 2022/11/30 13:39:23 INFO: Set nextTxnTs to 0
{"level":"info","ts":"2022-11-30T13:39:23.214Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-11-30T13:39:23.217Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-11-30T13:39:23.220Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-11-30T13:39:23.220Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I1130 13:39:23.322834       8 leaderelection.go:248] attempting to acquire leader lease flux-system/image-reflector-controller-leader-election...
I1130 13:39:31.593048       8 leaderelection.go:258] successfully acquired lease flux-system/image-reflector-controller-leader-election
{"level":"debug","ts":"2022-11-30T13:39:31.602Z","logger":"events","msg":"image-reflector-controller-69844c889c-vn679_f331ce73-b0e0-44eb-b810-759e0f36d391 became leader","type":"Normal","object":{"kind":"Lease","namespace":"flux-system","name":"image-reflector-controller-leader-election","uid":"92db0346-0e48-4ab0-9aa6-22b3503f4bde","apiVersion":"coordination.k8s.io/v1","resourceVersion":"25643914436"},"reason":"LeaderElection"}
{"level":"info","ts":"2022-11-30T13:39:31.609Z","msg":"Starting EventSource","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository","source":"kind source: *v1beta1.ImageRepository"}
{"level":"info","ts":"2022-11-30T13:39:31.612Z","msg":"Starting Controller","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository"}
{"level":"info","ts":"2022-11-30T13:39:31.614Z","msg":"Starting EventSource","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-11-30T13:39:31.615Z","msg":"Starting EventSource","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy","source":"kind source: *v1beta1.ImageRepository"}
{"level":"info","ts":"2022-11-30T13:39:31.616Z","msg":"Starting Controller","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy"}
{"level":"info","ts":"2022-11-30T13:39:31.729Z","msg":"Starting workers","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository","worker count":4}
{"level":"info","ts":"2022-11-30T13:39:31.731Z","msg":"Starting workers","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy","worker count":4}
{"level":"info","ts":"2022-11-30T13:39:31.743Z","msg":"no tags found in local storage for 'company-www-dev'","name":"company-www-dev","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"info","ts":"2022-11-30T13:39:31.743Z","msg":"no tags found in local storage for 'company-www-prod'","name":"company-www-prod","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:39:31.747Z","logger":"events","msg":"no tags found in local storage for 'company-www-dev'","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-dev","uid":"afb99c87-cc1e-4865-8326-4ecc19d4b304","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25100791204"},"reason":"info"}
{"level":"debug","ts":"2022-11-30T13:39:31.747Z","logger":"events","msg":"no tags found in local storage for 'company-www-prod'","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-prod","uid":"fc836851-c7c0-4dcc-a251-12d720606351","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25113288105"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:39:31.784Z","msg":"no tags found in local storage for 'company-www-dev'","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy","ImagePolicy":{"name":"company-www-dev","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-dev","reconcileID":"f9c51c56-08fe-4864-a029-25fb8726127a"}
{"level":"info","ts":"2022-11-30T13:39:31.785Z","msg":"no tags found in local storage for 'company-www-prod'","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy","ImagePolicy":{"name":"company-www-prod","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-prod","reconcileID":"0ed3991e-30b1-428d-86f6-7c56512488e8"}
{"level":"info","ts":"2022-11-30T13:39:31.787Z","msg":"no tags found in local storage for 'company-www-prod'","name":"company-www-prod","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:39:31.789Z","logger":"events","msg":"no tags found in local storage for 'company-www-prod'","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-prod","uid":"fc836851-c7c0-4dcc-a251-12d720606351","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25113288105"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:39:31.792Z","msg":"no tags found in local storage for 'company-www-prod'","controller":"imagepolicy","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImagePolicy","ImagePolicy":{"name":"company-www-prod","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-prod","reconcileID":"76af5147-d37e-47a1-bff9-b9f9e4277222"}
{"level":"info","ts":"2022-11-30T13:39:32.920Z","msg":"reconciliation finished in 1.182379079s, next run in 2m30s","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository","ImageRepository":{"name":"company-www-dev","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-dev","reconcileID":"575db200-8fb0-44c9-a78d-427bdaf0ae34"}
{"level":"info","ts":"2022-11-30T13:39:32.920Z","msg":"reconciliation finished in 1.179961406s, next run in 2m30s","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository","ImageRepository":{"name":"company-www-prod","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-prod","reconcileID":"ca5cb3c5-0f47-4f60-a090-5e35a10e1544"}
{"level":"info","ts":"2022-11-30T13:39:32.953Z","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.121258-e8fe8e2a-prod","name":"company-www-prod","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:39:32.954Z","logger":"events","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.121258-e8fe8e2a-prod","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-prod","uid":"fc836851-c7c0-4dcc-a251-12d720606351","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25113288105"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:39:32.958Z","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.085006-e8fe8e2a-dev","name":"company-www-dev","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:39:32.958Z","logger":"events","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.085006-e8fe8e2a-dev","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-dev","uid":"afb99c87-cc1e-4865-8326-4ecc19d4b304","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25100791204"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:42:03.796Z","msg":"reconciliation finished in 831.188112ms, next run in 2m30s","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository","ImageRepository":{"name":"company-www-dev","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-dev","reconcileID":"cc9a8d66-9677-490f-93d7-429b525c439f"}
{"level":"info","ts":"2022-11-30T13:42:03.819Z","msg":"reconciliation finished in 858.056601ms, next run in 2m30s","controller":"imagerepository","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageRepository","ImageRepository":{"name":"company-www-prod","namespace":"flux-system"},"namespace":"flux-system","name":"company-www-prod","reconcileID":"f77b3d60-76ed-49e9-adf5-2f99f98c0921"}
{"level":"info","ts":"2022-11-30T13:42:03.828Z","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.085006-e8fe8e2a-dev","name":"company-www-dev","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:42:03.829Z","logger":"events","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.085006-e8fe8e2a-dev","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-dev","uid":"afb99c87-cc1e-4865-8326-4ecc19d4b304","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25100791204"},"reason":"info"}
{"level":"info","ts":"2022-11-30T13:42:03.925Z","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.121258-e8fe8e2a-prod","name":"company-www-prod","namespace":"flux-system","reconciler kind":"ImagePolicy","reason":"info","annotations":null}
{"level":"debug","ts":"2022-11-30T13:42:03.926Z","logger":"events","msg":"Latest image tag for 'registry.gitlab.com/company/infra/website' resolved to: 221107.121258-e8fe8e2a-prod","type":"Normal","object":{"kind":"ImagePolicy","namespace":"flux-system","name":"company-www-prod","uid":"fc836851-c7c0-4dcc-a251-12d720606351","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25113288105"},"reason":"info"}

@pjbgf
Copy link
Member

pjbgf commented Nov 30, 2022

Changes required upstream in order to avoid the creation of empty commits: go-git/go-git#623 fluxcd/go-git#11.

Further investigation still needed to understand why this is happening.

@pjbgf
Copy link
Member

pjbgf commented Nov 30, 2022 •
edited
Loading

@srgvg I have created a RC image which blocks the empty commits from being created: ghcr.io/fluxcd/image-automation-controller:rc-10717892. Can you please give it a try?

It will simply log an error in the controller instead of creating empty commits. So at least other automations you have would be able to work normally.

@pjbgf
Copy link
Member

pjbgf commented Nov 30, 2022

@srgvg Does the repo where you observed this behaviour, have any of the below?

  • Symlinks
  • Git submodules
  • Git recurse submodules

@srgvg
Copy link
Author

srgvg commented Nov 30, 2022

@srgvg Does the repo where you observed this behaviour, have any of the below?

* Symlinks

* Git submodules

* Git recurse submodules

None. I does have a couple of GitRepository,spec.include repo's.

@srgvg
Copy link
Author

srgvg commented Nov 30, 2022

@srgvg I have created a RC image which blocks the empty commits from being created: ghcr.io/fluxcd/image-automation-controller:rc-10717892. Can you please give it a try?

It will simply log an error in the controller instead of creating empty commits. So at least other automations you have would be able to work normally.

Done & verified

➞  k get pod image-automation-controller-84d4447849-vwbsp -o yaml | grep -i image
  generateName: image-automation-controller-84d4447849-
    app: image-automation-controller
  name: image-automation-controller-84d4447849-vwbsp
    name: image-automation-controller-84d4447849
    image: ghcr.io/fluxcd/image-automation-controller:rc-10717892
    imagePullPolicy: IfNotPresent
  serviceAccount: image-automation-controller
  serviceAccountName: image-automation-controller
    image: ghcr.io/fluxcd/image-automation-controller:rc-10717892
    imageID: ghcr.io/fluxcd/image-automation-controller@sha256:16d412651c97f0960747267fdb60ae97412d6b39748abbe6410d6e093359b0c4

Seems like only a partial fix. Where I had 3 commit's in a row every $interval, I now have two:

k logs image-automation-controller-84d4447849-vwbsp -f
{"level":"info","ts":"2022-11-30T15:56:39.132Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-11-30T15:56:39.133Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-11-30T15:56:39.135Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
{"level":"info","ts":"2022-11-30T15:56:39.135Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
I1130 15:56:39.235714       1 leaderelection.go:248] attempting to acquire leader lease flux-system/image-automation-controller-leader-election...
I1130 15:56:39.360580       1 leaderelection.go:258] successfully acquired lease flux-system/image-automation-controller-leader-election
{"level":"info","ts":"2022-11-30T15:56:39.361Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImageUpdateAutomation"}
{"level":"info","ts":"2022-11-30T15:56:39.362Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-11-30T15:56:39.363Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-11-30T15:56:39.363Z","msg":"Starting Controller","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation"}
{"level":"info","ts":"2022-11-30T15:56:39.466Z","msg":"Starting workers","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","worker count":4}
{"level":"info","ts":"2022-11-30T15:56:44.642Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"04c5384c-cb7c-4bf4-8f97-203dcab471c8","revision":"2dddfa080483f7cca05e556a92f121d1d4f435b9","branch":"master"}
{"level":"info","ts":"2022-11-30T15:56:49.442Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"7fd0b579-7425-494b-9223-88d1f02b7d9a","revision":"94c06fca5ae9352ee306d2f2e9cd64cb1aec9204","branch":"master"}

@pjbgf
Copy link
Member

pjbgf commented Dec 1, 2022

@srgvg Are the empty commits still created in the target repository? Does the controller log any errors?

@pjbgf pjbgf changed the title multiple empty image update automation commits since flux2 0.37 Multiple empty commits since flux2 v0.37 Dec 1, 2022
@pjbgf pjbgf moved this to In Progress in Maintainers' Focus Dec 1, 2022
@pjbgf pjbgf self-assigned this Dec 1, 2022
@srgvg
Copy link
Author

srgvg commented Dec 1, 2022

Yes, same empty commits - except 2 per batch instead of three per batch like formerly. Logs were attached, not sure what extra information you are aiming on?

@pjbgf pjbgf mentioned this issue Dec 6, 2022
Merged
@stefanprodan stefanprodan mentioned this issue Dec 8, 2022
Closed
1 task
@pjbgf
Copy link
Member

pjbgf commented Dec 9, 2022

@srgvg we have just released a new RC, can you please retest and confirm whether it solves your issue?
ghcr.io/fluxcd/image-automation-controller:rc-bac68e9f

@srgvg
Copy link
Author

srgvg commented Dec 10, 2022

using image: ghcr.io/fluxcd/image-automation-controller:rc-bac68e9f

I'm afraid the same problem still persists:

14:47:37 ➞  k logs image-automation-controller-5b5b685c9d-wx7cs
{"level":"info","ts":"2022-12-10T13:45:46.630Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-12-10T13:45:46.633Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-12-10T13:45:46.636Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
{"level":"info","ts":"2022-12-10T13:45:46.636Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
I1210 13:45:46.736892       1 leaderelection.go:248] attempting to acquire leader lease flux-system/image-automation-controller-leader-election...
I1210 13:45:57.637698       1 leaderelection.go:258] successfully acquired lease flux-system/image-automation-controller-leader-election
{"level":"info","ts":"2022-12-10T13:45:57.638Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-10T13:45:57.639Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-12-10T13:45:57.639Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-12-10T13:45:57.639Z","msg":"Starting Controller","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-10T13:45:57.740Z","msg":"Starting workers","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","worker count":4}
{"level":"info","ts":"2022-12-10T13:46:01.443Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"fc0cebd7-bd15-4f94-8810-4f5d666ce2de","revision":"365581f5eccacc869b3a86167b7aee03e187d984","branch":"master"}
{"level":"info","ts":"2022-12-10T13:46:05.160Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"c38d5867-a843-4ea4-bb04-b8e2654d992d","revision":"c4e1a32e4e669e91237de71ede53a3c4e2f83a85","branch":"master"}

14:49:22 ➞  git show HEAD HEAD~1 HEAD~2
commit e8c1da1d110d33fef0969c842b4d47b3a05afcf4 (HEAD -> master, gitlab/master)
Author: k0-scw-autops-cloud <fluxcd@k0.scw.autops.cloud>
Date:   Sat Dec 10 13:48:33 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

commit b795d515f3b2be85f3c266f2df0e43ce886b2264
Author: k0-scw-autops-cloud <fluxcd@k0.scw.autops.cloud>
Date:   Sat Dec 10 13:48:12 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

enabled debug logging on the automation controller:

14:50:49 ➞  k logs image-automation-controller-5787ddcc8f-hkw78 -f
{"level":"info","ts":"2022-12-10T13:50:40.249Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-12-10T13:50:40.251Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-12-10T13:50:40.252Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-12-10T13:50:40.252Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I1210 13:50:40.352893       1 leaderelection.go:248] attempting to acquire leader lease flux-system/image-automation-controller-leader-election...
I1210 13:50:45.941351       1 leaderelection.go:258] successfully acquired lease flux-system/image-automation-controller-leader-election
{"level":"info","ts":"2022-12-10T13:50:45.942Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-10T13:50:45.942Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-12-10T13:50:45.942Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-12-10T13:50:45.942Z","msg":"Starting Controller","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation"}
{"level":"debug","ts":"2022-12-10T13:50:45.941Z","logger":"events","msg":"image-automation-controller-5787ddcc8f-hkw78_4a325101-03e5-4b10-8a65-a77c2041b26a became leader","type":"Normal","object":{"kind":"Lease","namespace":"flux-system","name":"image-automation-controller-leader-election","uid":"f9e1df7d-9f10-42d8-8cee-386df3e434de","apiVersion":"coordination.k8s.io/v1","resourceVersion":"25890788307"},"reason":"LeaderElection"}
{"level":"info","ts":"2022-12-10T13:50:46.045Z","msg":"Starting workers","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","worker count":4}
{"level":"debug","ts":"2022-12-10T13:50:46.046Z","msg":"fetching git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"6974fe0d-4416-4305-ad7b-dc9109efd25b","gitrepository":{"namespace":"flux-system","name":"flux-system"}}
{"level":"debug","ts":"2022-12-10T13:50:46.047Z","msg":"attempting to clone git repository","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"6974fe0d-4416-4305-ad7b-dc9109efd25b","gitrepository":{"namespace":"flux-system","name":"flux-system"},"ref":{"branch":"master"},"working":"/tmp/flux-system-flux-system3181979023"}
{"level":"debug","ts":"2022-12-10T13:50:47.940Z","msg":"updating with setters according to image policies","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"6974fe0d-4416-4305-ad7b-dc9109efd25b","count":2,"manifests-path":"/tmp/flux-system-flux-system3181979023/k8s/clusters/k0.scw.autops.cloud"}
{"level":"debug","ts":"2022-12-10T13:50:47.960Z","msg":"ran updates to working dir","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"6974fe0d-4416-4305-ad7b-dc9109efd25b","working":"/tmp/flux-system-flux-system3181979023"}
{"level":"info","ts":"2022-12-10T13:50:49.627Z","msg":"Committed and pushed change c74f6512ceafdca9330a1bb89da7331b31d5aa68 to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","name":"flux-system","namespace":"flux-system","reconciler kind":"ImageUpdateAutomation","reason":"info","annotations":null}
{"level":"debug","ts":"2022-12-10T13:50:49.628Z","logger":"events","msg":"Committed and pushed change c74f6512ceafdca9330a1bb89da7331b31d5aa68 to master\nAutomated image update flux-system/flux-system\n\nImages:\nObjects:\nFiles:\n","type":"Normal","object":{"kind":"ImageUpdateAutomation","namespace":"flux-system","name":"flux-system","uid":"e916aa18-6d8c-4994-8e6e-89f42c2bb980","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"25890756929"},"reason":"info"}
{"level":"info","ts":"2022-12-10T13:50:49.635Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"6974fe0d-4416-4305-ad7b-dc9109efd25b","revision":"c74f6512ceafdca9330a1bb89da7331b31d5aa68","branch":"master"}

showing that last referenced commit:

14:52:06 ➞  git show c74f6512ceafdca9330a1bb89da7331b31d5aa68
commit c74f6512ceafdca9330a1bb89da7331b31d5aa68 (HEAD -> master, gitlab/master)
Author: k0-scw-autops-cloud <fluxcd@k0.scw.autops.cloud>
Date:   Sat Dec 10 13:50:48 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

@devopstagon
Copy link

Can confirm I am seeing the exact same behavior.

flux version
flux: v0.36.0
helm-controller: v0.27.0
image-automation-controller: v0.27.0
image-reflector-controller: v0.23.0
kustomize-controller: v0.31.0
notification-controller: v0.29.0
source-controller: v0.32.1

@pjbgf
Copy link
Member

pjbgf commented Dec 15, 2022

@devopstagon what Git server are you using? Any further information you can provide, as we are still not able to fully reproduce this.

@srgvg @devopstagon we are making changes to fix another issue on IAC. Do you mind trying to reproduce the issue with this image please: ghcr.io/fluxcd/image-automation-controller:rc-982331e6.

@srgvg
Copy link
Author

srgvg commented Dec 15, 2022

Not solved with rc-982331e6, but an improvement: Now only 1 empty commit (instead of two with the previous rc, and three with the one before that).

image automation logs:

{"level":"info","ts":"2022-12-15T16:53:30.857Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-12-15T16:53:30.859Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-12-15T16:53:30.860Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-12-15T16:53:30.860Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I1215 16:53:30.961684       1 leaderelection.go:248] attempting to acquire leader lease flux-system/image-automation-controller-leader-election...
I1215 16:53:30.992218       1 leaderelection.go:258] successfully acquired lease flux-system/image-automation-controller-leader-election
{"level":"info","ts":"2022-12-15T16:53:30.994Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-15T16:53:30.994Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-12-15T16:53:30.994Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-12-15T16:53:30.994Z","msg":"Starting Controller","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-15T16:53:31.097Z","msg":"Starting workers","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","worker count":4}
{"level":"info","ts":"2022-12-15T16:53:35.072Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"ec5ce6ed-7db4-4b6c-9e8a-ba479fe2ae89","revision":"1c4759bfb1cf2d3642718b8ed5ce0502705565ab","branch":"master"}
{"level":"info","ts":"2022-12-15T16:55:30.165Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"1ccc15dd-bb94-4308-801b-a6563da561b0","revision":"60af292ed428359ff3e33ed5cc515d3734c5cc9f","branch":"master"}
{"level":"info","ts":"2022-12-15T16:55:34.186Z","msg":"pushed commit to origin","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"a4b879cd-e400-4d1f-997e-94ce13900636","revision":"81f8ba01207bd161f015f526f792c6efb416968d","branch":"master"}

Although, in z couple of minutes there were 3 commits, 1 first, and then some minutes later two other, only 4 seconds apart....

➞  git show gitlab/master gitlab/master~1 gitlab/master~2 gitlab/master~3
commit 81f8ba01207bd161f015f526f792c6efb416968d (gitlab/master)
Author: k0-scw-autops-cloud <fluxcd@k0.scw.autops.cloud>
Date:   Thu Dec 15 16:55:32 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

commit 60af292ed428359ff3e33ed5cc515d3734c5cc9f
Author: k0-scw-autops-cloud <fluxcd@k0.scw.autops.cloud>
Date:   Thu Dec 15 16:55:28 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

commit 1c4759bfb1cf2d3642718b8ed5ce0502705565ab
Author: k0-scw-autops-cloud <fluxcd@k0.scw.autops.cloud>
Date:   Thu Dec 15 16:53:33 2022 +0000

    Automated image update flux-system/flux-system

    Images:
    Objects:
    Files:

commit 5b2ced040dab4d5e883aefe3b8769cc12491737e (HEAD -> master, github/master)
Author: Serge van Ginderachter <serge@vanginderachter.be>
Date:   Thu Dec 15 17:51:23 2022 +0100

    image automation bug rc update

    https://github.com/fluxcd/image-automation-controller/issues/466#issuecomment-1353375904

diff --git k8s/clusters/k0.scw.autops.cloud/flux-system/kustomization.yaml k8s/clusters/k0.scw.autops.cloud/flux-system/kustomization.yaml
index 45cc3c9..5be772b 100644
--- k8s/clusters/k0.scw.autops.cloud/flux-system/kustomization.yaml
+++ k8s/clusters/k0.scw.autops.cloud/flux-system/kustomization.yaml
@@ -52,4 +52,4 @@ patches:

 images:
   - name: ghcr.io/fluxcd/image-automation-controller
-    newTag: rc-bac68e9f
+    newTag: rc-982331e6

Let me know if I can provide more info.

@srgvg
Copy link
Author

srgvg commented Dec 15, 2022

The next "run" I see again 3 commits, though not all at the same exact second

➞  git log gitlab/master  | grep Date: | head -n 3
Date:   Thu Dec 15 16:58:41 2022 +0000
Date:   Thu Dec 15 16:58:06 2022 +0000
Date:   Thu Dec 15 16:58:02 2022 +0000

@pjbgf
Copy link
Member

pjbgf commented Dec 15, 2022

@srgvg found another execution path that could be leading to this. Here's an image with the fix: ghcr.io/fluxcd/image-automation-controller:rc-7a111045.

@devopstagon
Copy link

devopstagon commented Dec 15, 2022 •
edited
Loading

@pjbgf To be clear I am using GitLab. That being said I tested the fix and it does indeed solve the issues. I have had 0 commits now after 20 minutes. Will leave it overnight and see.

@srgvg
Copy link
Author

srgvg commented Dec 16, 2022

Looks like this is solved now, indeed.

➞  k logs image-automation-controller-95fc647bb-6mkrh  -f
{"level":"info","ts":"2022-12-16T09:00:17.624Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-12-16T09:00:17.625Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-12-16T09:00:17.626Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-12-16T09:00:17.627Z","msg":"Starting server","kind":"health probe","addr":"[::]:9440"}
I1216 09:00:17.727804       1 leaderelection.go:248] attempting to acquire leader lease flux-system/image-automation-controller-leader-election...
I1216 09:00:17.751931       1 leaderelection.go:258] successfully acquired lease flux-system/image-automation-controller-leader-election
{"level":"info","ts":"2022-12-16T09:00:17.752Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-16T09:00:17.752Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta2.GitRepository"}
{"level":"info","ts":"2022-12-16T09:00:17.752Z","msg":"Starting EventSource","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","source":"kind source: *v1beta1.ImagePolicy"}
{"level":"info","ts":"2022-12-16T09:00:17.752Z","msg":"Starting Controller","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation"}
{"level":"info","ts":"2022-12-16T09:00:17.853Z","msg":"Starting workers","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","worker count":4}
{"level":"info","ts":"2022-12-16T09:00:19.991Z","msg":"no changes made in working directory; no commit","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"b0bce329-212f-4311-955d-6c223df1b025"}
{"level":"info","ts":"2022-12-16T09:00:21.985Z","msg":"no changes made in working directory; no commit","controller":"imageupdateautomation","controllerGroup":"image.toolkit.fluxcd.io","controllerKind":"ImageUpdateAutomation","ImageUpdateAutomation":{"name":"flux-system","namespace":"flux-system"},"namespace":"flux-system","name":"flux-system","reconcileID":"4155e67f-3e4c-4a1f-a784-82ba66df6fa0"}

30 minutes later and still nothing. Sounds like solved.

@pjbgf
Copy link
Member

pjbgf commented Dec 16, 2022

Excellent, thank you @devopstagon and @srgvg for testing it and reporting back. We will soon release an official version with the fix.

@srgvg
Copy link
Author

srgvg commented Dec 16, 2022

Thank you for your work. Looking forward!

@pjbgf pjbgf mentioned this issue Dec 20, 2022
Merged
Repository owner moved this from In Progress to Since Last Dev Meeting in Maintainers' Focus Dec 20, 2022
@pjbgf
Copy link
Member

pjbgf commented Dec 21, 2022

The new official image automation controller image contains the fix: ghcr.io/fluxcd/image-automation-controller:v0.28.0.
We are in the process of releasing Flux v0.38.0 which will include that image.

@pjbgf pjbgf mentioned this issue Jan 6, 2023
Closed
@SonalinP
Copy link

I am facing the similar issue where without any new changes , flux is committing to git in every 1min(in my case).
Is there any workaround for this ?

installed versions :
flux version 0.37.0
helm-controller:v0.27.0
kustomize-controller:v0.31.0
image-automation-controller:v0.27.0
image-reflector-controller:v0.23.0
source-controller:v0.32.1

@srgvg
Copy link
Author

srgvg commented Feb 14, 2023

@SonalinP well, yes, upgrade Flux to 0.38.3 or 0.39.0.

@souleb souleb moved this from Since Last Dev Meeting to Done in Maintainers' Focus Feb 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@pjbgf pjbgf

Labels
area/git Git related issues and pull requests bug Something isn't working
Projects
Maintainers' Focus
Status: Done
Milestone
GA
Development

Successfully merging a pull request may close this issue.

Block the creation of empty commits fluxcd/image-automation-controller
5 participants
@srgvg @pjbgf @aryan9600 @SonalinP @devopstagon