sas-run-tool: Service executor failed to execute successfully: exit status 1

[drhorg]

We have installed Viya 4 Kubernetes, and deployed OpenSearch Dashboards for logging . I see the error

Logsource: sas-run-tool 

message : Tool executor failed starting service: exit status 1

Level : Error 

then right after

Level : Fatal 

Logsource: sas-run-tool 

message : Service executor failed to execute successfully: exit status 1

Level : Fatal 

Did it happen in your environment and you know what this is? I googled but did not find much for this error. 

Thanks a lot,

[gwootton]

What is the name of the pod that is throwing these messages?

[drhorg]

Hi @gwootton , sorry for delay, missed your reply. 

kube.pod - sas-backup-purge-job

level -fatal

kube.container - sas-backup-purge-job

kube.annotations.sas_com/component-name

sas-backup-job

Please let me know if any other info needed. 

thank you!

[gwootton · Accepted solution]

The sas-backup-purge-job I think runs daily and removes old backups, this message suggests one such execution of a job failed. If you look at your job history do you see these show as completed?
kubectl -n namespace get jobs -l app.kubernetes.io/name=sas-backup-purge-job

[drhorg]

Hi @gwootton , yes the purge failed multiple times. Sorry by mistake I accepted my reply as solution instead of your reply. I fixed this now.

thank you for your help!

[paterd2]

Greg, 

sometimes my backup gives failed in viya 24.03.

I cannot find the reason, because if I fire this job again, it succeeds.

Maybe you have a solution ?

Regards,

Dik

{"level":"info","version":1,"source":"sas-backupjob","messageKey":"Checking if job is allowed to run.","properties":{"logger":"backupjob","caller":"backupjob/main.go:314"},"timeStamp":"2024-12-13T02:02:04.280263+01:00","message":"Checking if job is allowed to run."}
{"level":"info","version":1,"source":"sas-backupjob","messageKey":"backupjob-log-icu.updating.k8s.job.labels.info.log","messageParameters":{"jobName":"sas-scheduled-backup-dpyxjx3i-28900860"},"properties":{"logger":"backupjob/kubeutils","caller":"kubeutils/kube_client.go:126"},"timeStamp":"2024-12-13T02:02:04.334724+01:00","message":"Updating the Kubernetes job sas-scheduled-backup-dpyxjx3i-28900860 with given label."}
{"level":"info","version":1,"source":"sas-backupjob","messageKey":"backupjob-log-icu.updated.k8s.job.info.log","messageParameters":{"jobName":"sas-scheduled-backup-dpyxjx3i-28900860"},"properties":{"logger":"backupjob/kubeutils","caller":"kubeutils/kube_client.go:152"},"timeStamp":"2024-12-13T02:02:04.345526+01:00","message":"Updated the Kubernetes job the sas-scheduled-backup-dpyxjx3i-28900860."}
{"level":"error","version":1,"source":"sas-backupjob","messageKey":"Job is not allowed to run.","properties":{"logger":"backupjob","caller":"backupjob/main.go:476"},"timeStamp":"2024-12-13T02:02:04.345565+01:00","message":"Job is not allowed to run."}
{"level":"error","version":1,"source":"sas-backupjob","messageKey":"backupjob-log-icu.remote.backup.agent.process.grep.pid.error.log","messageParameters":{"error":"exit status 1"},"properties":{"logger":"backupjob","caller":"backupjob/main.go:529"},"timeStamp":"2024-12-13T02:04:14.495204+01:00","message":"backupjob-log-icu.remote.backup.agent.process.grep.pid.error.log [error:exit status 1]"}
{"level":"error","version":1,"source":"sas-run-tool","messageKey":"Tool executor failed starting service: exit status 1","properties":{"logger":"tools/run","caller":"impl/executor.go:69"},"timeStamp":"2024-12-13T02:04:14.497860+01:00","message":"Tool executor failed starting service: exit status 1"}
{"level":"fatal","version":1,"source":"sas-run-tool","messageKey":"Service executor failed to execute successfully: exit status 1","properties":{"logger":"tools/run","caller":"impl/tooling.go:139"},"timeStamp":"2024-12-13T02:04:14.497901+01:00","message":"Service executor failed to execute successfully: exit status 1"}

[gwootton]

The failure message here is "Job is not allowed to run." Usually this happens because another backup is already running.

[paterd2]

Greg, thank you, but I don't run 2 backups in the night, can I simutlate the check that a backup is already running ?

[gwootton]

From what I can tell keys are created in the SAS Configuration Server with the backup job id (e.g. backup-job-uuid or backup-job-incr-uuid). It checks if such a key is present and, depending on the type of backup being requested will stop if it finds one. It would also stop if it can't create such a key.
You may want to turn on debug logging of the backup, this should provide more detail on the failure. To do that, you could set the environment variable SAS_LOG_LEVEL_BACKUPJOB to debug on the cronjob, for example:
kubectl -n namespace set env cronjob/sas-scheduled-backup-job SAS_LOG_LEVEL_BACKUPJOB=DEBUG

[paterd2]

Greg, thank you, now we have more output, we will investigate further..

[paterd2]

Greg, we found it.

the sas-backup-purge-job cannot run simultaneous with the sas-scheduled-backup-job.

So this explains why it went ok if we run it by hand in the morning.

We will reschedule the full backups.

kubectl -n $ns get cronjob | grep backup | grep False
sas-backup-purge-job 15 0 1/1 * ? False 0 8h 127d
sas-scheduled-backup-job 0 1 * * 0 False 0 4d8h 127d
sas-scheduled-backup-kbx7pj33 0 1 * * 1-5 False 0 8h 16d

Adjusted to :
sas-backup-purge-job 15 0 1/1 * ? False 0 8h 127d
sas-scheduled-backup-job 0 4 * * 0 False 0 4d8h 127d
sas-scheduled-backup-kbx7pj33 0 4 * * 1-5 False 0 8h 16d

Tomorrow we know it for sure.