[BUG] Problem with long running phase

[blafry]

Describe the bug

When phase takes about 6 hours, the operator (0.81.0) does not set the snapshot_id in the ActionSet despite using kando for this purpose.

To Reproduce
Steps to reproduce the behavior:

Blueprint:

  backup:
    kind: Deployment
    outputArtifacts:
      mysql_backup:
        keyValue:
          snapshot_id: '{{ .Phases.backupMySQL.Output.snapshot_id }}'
    phases:
      - args:
          command:
            - bash
            - '-o'
            - errexit
            - '-o'
            - pipefail
            - '-o'
            - errtrace
            - '-c'
            - |
              sleep 20000
              kando output snapshot_id 6c1b0940
          namespace: mysql
        func: KubeTask
        name: backupMySQL

ActionSet describe:

Name:         backup-mysql-2022-09-04-00-00
Namespace:    mysql
Labels:       <none>
Annotations:  <none>
API Version:  cr.kanister.io/v1alpha1
Kind:         ActionSet

(...)

Spec:
  Actions:
    Blueprint:  service-backups-mysql
    Name:       backup
    Object:
      API Version:      
      Group:            
      Kind:             Deployment
      Name:             platform-operator-mysql
      Namespace:        mysql
      Resource:         
    Preferred Version:  
Status:
  Actions:
    Artifacts:
      mysql_backup:
        Key Value:
          snapshot_id:  {{ .Phases.backupMySQL.Output.snapshot_id }}
    Blueprint:          service-backups-mysql
    Name:               backup
    Object:
      API Version:  
      Group:        
      Kind:         Deployment
      Name:         platform-operator-mysql
      Namespace:    mysql
      Resource:     
    Phases:
      Name:   backupMySQL
      State:  complete
  Error:
    Message:  Failed to render template: "snapshot_id" not found
  State:      failed
Events:       <none>

Operator logs:

2022-09-04T00:00:03.815136760Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).logAndSuccessEvent","Line":643,"hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Executing action backup","time":"2022-09-04T00:00:03.813944563Z"}
2022-09-04T00:00:03.977164547Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).handleActionSet","Line":396,"NewActionSetName":"backup-mysql-2022-09-04-00-00","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Created actionset and started executing actions","time":"2022-09-04T00:00:03.974906861Z"}
2022-09-04T00:00:03.977216450Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).logAndSuccessEvent","Line":643,"Phase":"backupMySQL","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Executing phase backupMySQL","time":"2022-09-04T00:00:03.975206032Z"}
2022-09-04T00:00:03.981810552Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onUpdateActionSet","Line":238,"Status":"pending","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Updated ActionSet","time":"2022-09-04T00:00:03.97779321Z"}
2022-09-04T00:00:03.981852784Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onUpdateActionSet","Line":245,"Phase":"backupMySQL-\u003epending","Status":"running","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Updated ActionSet","time":"2022-09-04T00:00:03.977920245Z"}
2022-09-04T05:33:30.055810444Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).logAndSuccessEvent","Line":643,"Phase":"backupMySQL","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Completed phase backupMySQL","time":"2022-09-04T05:33:30.055486706Z"}
2022-09-04T05:33:30.072749945Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).onUpdateActionSet","Line":238,"Status":"failed","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Updated ActionSet","time":"2022-09-04T05:33:30.072434534Z"}
2022-09-04T05:33:30.072820757Z {"ActionSet":"backup-mysql-2022-09-04-00-00","File":"pkg/controller/controller.go","Function":"github.com/kanisterio/kanister/pkg/controller.(*Controller).logAndErrorEvent","Line":626,"Phase":"backupMySQL","error":"Failed to render template: \"snapshot_id\" not found","hostname":"service-operator-kanister-764b48bbb-2m6cx","level":"info","msg":"Failed to render output artifacts","time":"2022-09-04T05:33:30.072552115Z"}

Expected behavior
An artifact has been set, key: snapshot_id value: 6c1b0940

Environment
Kubernetes Version/Provider: 1.22
Cluster Size (#nodes): 1

Additional context
Instead of sleep 20000 in my blueprint there is a mysqldump which output is streamed to the restic repository. Due to the size of the database and limited bandwidth, this is how long it takes. In the case of a shorter time, I was unable to reproduce the problem.

[github-actions]

Thanks for opening this issue 👍. The team will review it shortly.

If this is a bug report, make sure to include clear instructions how on to reproduce the problem with minimal reproducible examples, where possible. If this is a security report, please review our security policy as outlined in SECURITY.md.

If you haven't already, please take a moment to review our project's Code of Conduct document.

[ihcsim]

@blafry thanks for reporting this issue. We are still trying to reproduce this; will keep you updated once we make progress. Meanwhile, feel free to join Slack, if you have other questions.

[blafry]

@ihcsim hi, did you reproduce the problem?

[viveksinghggits]

Hi @blafry,
We were able to reproduce the problem, and also decided who is going to look into this soon. I will update the progress here.

[pavannd1]

@akankshakumari393 Please take this one

[akankshakumari393]

We have started working on the issue, but unfortunately we don't have the resolution yet. I will keep updating the progress here.

[github-actions]

This issue is marked as stale due to inactivity. Add a new comment to reactivate it.

[blafry]

@akankshakumari393 hello, any progress?

[akankshakumari393]

We were able to reproduce the issue, it happens only in cases where the action keeps running for more than 5 hrs. We are still looking into it.

[github-actions]

This issue is marked as stale due to inactivity. Add a new comment to reactivate it.

[maksym-herbert]

Any updates?

[DCkQ6]

Any updates?

[viveksinghggits]

Hi @DCkQ6 ,
We will have to re-prioritise this issue. Can you please share how long your phase is expected to take to get completed successfully?

[DCkQ6]

In the worst case backup of our problematic huge database takes about 7h

[viveksinghggits]

In the worst case backup of our problematic huge database takes about 7h

Thank you, I will make sure that I bring this up in coming community call.

[blafry]

Hi @viveksinghggits! Any updates after community call?

[viveksinghggits]

Hi @blafry ,
Yes, we did discuss this and decided that we should accept it and work on this, that's why the accepted label was added. The problem is we have not prioritised this right now. Do you have some familiarity with Go, would you like to take a stab at it? I would be more than happy to help you with any questions you have.

[mlavi]

As discussed in today's community meeting, this also came up recently in our Slack channel with a proposed solution. @e-sumin can you take a look?