"SSH could not read data: Error waiting on socket" when using libgit2

[squaremo]

https://cloud-native.slack.com/archives/CLAJ40HV3/p1625133279255100

This is reported in the logs:

{
  "level": "error",
  "ts": "2021-07-01T07:44:10.656Z",
  "logger": "controller-runtime.manager.controller.imageupdateautomation",
  "msg": "Reconciler error",
  "reconciler group": "image.toolkit.fluxcd.io",
  "reconciler kind": "ImageUpdateAutomation",
  "name": "redacted",
  "namespace": "flux-system",
  "error": "unable to clone 'ssh://git@github.com/redacted/redacted.git', error: SSH could not read data: Error waiting on socket"
}

.. though apparently not all the time, as

After adding [update markers], Image Automation controller started to update files for me.

Source controller reportedly manages to clone the repo (all the time?) when set to use libgit2, and changing to an RSA key didn't stop the error messages. EDIT: no, not all the time -- source-controller also fails intermittently, indicating that the problem is in the code in source-controller/pkg that source-controller and image-automation-controller both use.

[rjhenry]

I've found a solution that worked for me, at least - there gitrepo definition had a URL ending in .git; removing this then worked.
Before: .spec.url: ssh://git@github.com/orgname/repo.git
After: .spec.url: ssh://git@github.com/orgname/repo

Why it worked, I'm not sure - but I happened to stumble across the difference between a working and a non-working cluster.

[morganchristiansson]

I am getting this cloning from localhost git repo with openssh+gitolite.

It's not transient every time error waiting on socket.

Same GitRepository works perfectly from source-controller. In image-automation-controller this error:

{
	"level": "error",
	"ts": "2021-07-29T15:54:57.687Z",
	"logger": "controller-runtime.manager.controller.imageupdateautomation",
	"msg": "Reconciler error",
	"reconciler group": "image.toolkit.fluxcd.io",
	"reconciler kind": "ImageUpdateAutomation",
	"name": "flux-system",
	"namespace": "flux-system",
	"error": "unable to clone 'ssh://git@morgan-server.lan/k3s.git', error: SSH could not read data: Error waiting on socket"
}

[rjhenry]

I've found a solution that worked for me, at least - there gitrepo definition had a URL ending in .git; removing this then worked.
Before: .spec.url: ssh://git@github.com/orgname/repo.git
After: .spec.url: ssh://git@github.com/orgname/repo

Why it worked, I'm not sure - but I happened to stumble across the difference between a working and a non-working cluster.

I think this is a significant red herring; a few instances now with the .git-less syntax still hangs. The repository is about 20M and the cluster has a gig pipe to the internet, so it shouldn't be a timeout when trying to clone.

Is it possible to get the image-automation-controller to die in the event of these errors so the scheduler can simply recreate it?

[rjhenry]

For the record, this occurs with both libgit2 and go-git gitImplementationson the gitRepository resource; I've switched back to go-git as the source controller seemed much happier with that.

[morganchristiansson]

Are there any suggestions on how to debug this further? Any flags to enable debug logging? Or maybe tcpdump?

[ozlotusflare]

Hey everyone!
After upgrade FluxCD2 to the latest version I faced with the same issue :(
I checked gitRepository CRD and by default is go-git gitImplementationson, I've tried to change to libgit2, but still have errors:

{
  "level": "error",
  "ts": "2021-09-07T11:35:38.559Z",
  "logger": "controller-runtime.manager.controller.imageupdateautomation",
  "msg": "Reconciler error",
  "reconciler group": "image.toolkit.fluxcd.io",
  "reconciler kind": "ImageUpdateAutomation",
  "name": "image-update-automation-myrepo",
  "namespace": "test-ns",
  "error": "unable to clone ssh://git@github.com/repo/myrepo, error: SSH could not read data: Error waiting on socket"
}

Any thoughts , how to fix this ?
Thanks 🙏

[rjhenry]

Are there any suggestions on how to debug this further? Any flags to enable debug logging? Or maybe tcpdump?

I was taking a look at this, and it appears that only way to enable debug logging is to edit the deployment of the image-automation-controller. It's a relatively simple change - in your gotk-components.yaml, make the following change:

@@ -5235,7 +5235,7 @@ spec:
       - args:
         - --events-addr=http://notification-controller/
         - --watch-all-namespaces=true
-        - --log-level=info
+        - --log-level=debug
         - --log-encoding=json
         - --enable-leader-election
         env:

I'm now running this in a couple of clusters, so hopefully will get more information that can be contributed to this issue.

[rjhenry]

I've noted a failure to clone, within only a few minutes of starting one of the pods:

{"level":"info","ts":"2021-09-08T08:58:41.670Z","logger":"setup","msg":"starting manager"}
<..>
{"level":"debug","ts":"2021-09-08T09:02:02.075Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"ran updates to working dir","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system","working":"/tmp/flux-system-flux-system244015386"}
{"level":"debug","ts":"2021-09-08T09:02:02.097Z","logger":"controller-runtime.manager.events","msg":"Normal","object":{"kind":"ImageUpdateAutomation","namespace":"flux-system","name":"flux-system","uid":"c9b53014-a6e7-4e65-87f6-7d254c417baa","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"52286285"},"reason":"info","message":"no updates made"}
{"level":"debug","ts":"2021-09-08T09:02:02.098Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"no changes made in working directory; no commit","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system"}
{"level":"debug","ts":"2021-09-08T09:03:02.134Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"fetching git repository","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system","gitrepository":{"namespace":"flux-system","name":"flux-system"}}
{"level":"debug","ts":"2021-09-08T09:03:02.134Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"using git repository ref from .spec.git.checkout","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system","ref":{"branch":"main"}}
{"level":"debug","ts":"2021-09-08T09:03:02.134Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"using push branch from .spec.push.branch","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system","branch":"main"}
{"level":"debug","ts":"2021-09-08T09:03:02.134Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"attempting to clone git repository","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system","gitrepository":{"namespace":"flux-system","name":"flux-system"},"ref":{"branch":"main"},"working":"/tmp/flux-system-flux-system796571057"}
{"level":"debug","ts":"2021-09-08T09:03:03.695Z","logger":"controller-runtime.manager.events","msg":"Normal","object":{"kind":"ImageUpdateAutomation","namespace":"flux-system","name":"flux-system","uid":"c9b53014-a6e7-4e65-87f6-7d254c417baa","apiVersion":"image.toolkit.fluxcd.io/v1beta1","resourceVersion":"52286696"},"reason":"error","message":"unable to clone 'ssh://git@github.com/<GITHUB_GROUP>/<GITOPS_REPO>', error: SSH could not read data: Error waiting on socket"}
{"level":"error","ts":"2021-09-08T09:03:03.709Z","logger":"controller-runtime.manager.controller.imageupdateautomation","msg":"Reconciler error","reconciler group":"image.toolkit.fluxcd.io","reconciler kind":"ImageUpdateAutomation","name":"flux-system","namespace":"flux-system","error":"unable to clone 'ssh://git@github.com/<GITHUB_GROUP>/<GITOPS_REPO>', error: SSH could not read data: Error waiting on socket","stacktrace":"sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.9.5/pkg/internal/controller/controller.go:253\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.9.5/pkg/internal/controller/controller.go:214"}

Interestingly, there were only two time windows during which this complaint was made:

$ grep 'unable to clone' flux-iac-broken-debug.log | jq '.ts'
"2021-09-08T09:03:03.695Z"
"2021-09-08T09:03:03.709Z"
"2021-09-08T10:46:06.474Z"
"2021-09-08T10:46:06.491Z"

[squaremo]

For the record, this occurs with both libgit2 and go-git gitImplementationson the gitRepository

image-automation-controller always uses libgit2 for cloning, mainly because the go-git implementation does a shallow clone (and this makes branching difficult to impossible). Did source-controller have any problems when you switched the implementation to libgit2? I gather not -- that's what makes this truly mysterious, because it is running the same code.

[rjhenry]

I thought there were issues with both the image automation controller and the source controller, but I've dug through our logging server and found records at the time the change was made. It looks like the problems were with the image-automation-controller, which was immediately failing to clone the repository just minutes after the change was merged. It appears to be the same issue as before, just immediate rather than after some delay.

[squaremo]

which was immediately failing to clone the repository just minutes after the change was merged.

Which change was merged -- did I miss a vital clue?

[rjhenry]

which was immediately failing to clone the repository just minutes after the change was merged.

Which change was merged -- did I miss a vital clue?

Sorry, that's my own terrible wording - the change was from go-git to libgit2 for the gitImplementation on my gitRepository objects.

[rjhenry]

@squaremo If it's any use, I can provide debug-level logs from a controller pod - I'd prefer to do so directly via Slack, though, as I'm not entirely comfortable posting unredacted logs on a public issue.

[squaremo]

If it's any use, I can provide debug-level logs from a controller pod - I'd prefer to do so directly via Slack, though, as I'm not entirely comfortable posting unredacted logs on a public issue.

Worth a try! I'm Michael Bridgen in CNCF slack.

[squaremo]

OK, thanks to lots of digging through logs from @rjhenry, I think we have established that this happens for source-controller as well, when the GitRepository object has gitImplementation: libgit2[1]. It seems to be less frequent in the source-controller, but it's already intermittent with image-automation-controller[2] so difficult to judge.

[1] the same "SSH could not read data: Error waiting on socket" error message appears in the source-controller logs, inside a period when the GitRepository was known (in git history!) to have that setting
[2] the image-automation logs show a failure, then a success, without a config change in the meantime