vim.fault.FileNotFound during begin.py

[legoktm]

May 03 18:33:05 ws-ci-bastion ws-ci-runner[145282]: ERROR: Program 3692 completed with Failure
May 03 18:33:05 ws-ci-bastion ws-ci-runner[145282]: ERROR: More info on process
May 03 18:33:05 ws-ci-bastion ws-ci-runner[145282]: (vim.vm.guest.ProcessManager.ProcessInfo) [
                                                       (vim.vm.guest.ProcessManager.ProcessInfo) {
                                                          dynamicType = <unset>,
                                                          dynamicProperty = (vmodl.DynamicProperty) [],
                                                          name = 'qvm-run',
                                                          pid = 3692,
                                                          owner = 'user',
                                                          cmdLine = '"/usr/bin/qvm-run" sd-dev /usr/bin/python3 /home/user/bin/begin.py',
                                                          startTime = 2024-05-03T18:30:21Z,
                                                          endTime = 2024-05-03T18:33:06Z,
                                                          exitCode = 1
                                                       }
                                                    ]
May 03 18:33:05 ws-ci-bastion ws-ci-runner[145282]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                       dynamicType = <unset>,
                                                       dynamicProperty = (vmodl.DynamicProperty) [],
                                                       msg = 'File /home/user/2024-05-03-182742943929-9ee06867c586739cf357777e2c49d0a577f84bbb-Qubes_4.2_C-update_20240503045634.log.txt was not found',
                                                       faultCause = <unset>,
                                                       faultMessage = (vmodl.LocalizableMessage) [],
                                                       file = '/home/user/2024-05-03-182742943929-9ee06867c586739cf357777e2c49d0a577f84bbb-Qubes_4.2_C-update_20240503045634.log.txt'
                                                    }

(corresponds to freedomofpress/securedrop-workstation@9ee0686)

[legoktm]

This happens every so often it seems:

Apr 24 21:58:01 ws-ci-bastion ws-ci-runner[16884]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-24-210516473254-11916be2ed94907f7c1ec645914de5aa4838c1fb-Qubes_4.2_A-update_20240424043652.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-24-210516473254-11916be2ed94907f7c1ec645914de5aa4838c1fb-Qubes_4.2_A-update_20240424043652.log.txt'
                                                   }
Apr 24 22:01:05 ws-ci-bastion ws-ci-runner[16972]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-24-210821981630-49961c20db9114294c5c0e7ef2094f4969cdac27-Qubes_4.2_A-update_20240424043652.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-24-210821981630-49961c20db9114294c5c0e7ef2094f4969cdac27-Qubes_4.2_A-update_20240424043652.log.txt'
                                                   }
Apr 25 06:39:22 ws-ci-bastion ws-ci-runner[29709]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-25-063003605073-4aa1607de3f02d1c19066453e97308a49001328a-Qubes_4.2_A-update_20240425043702.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-25-063003605073-4aa1607de3f02d1c19066453e97308a49001328a-Qubes_4.2_A-update_20240425043702.log.txt'
                                                   }
Apr 25 20:22:54 ws-ci-bastion ws-ci-runner[58952]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-25-201552054070-cab3216e7ed6ec13b8445802da7e0a8dd8602950-Qubes_4.2_A-update_20240425043702.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-25-201552054070-cab3216e7ed6ec13b8445802da7e0a8dd8602950-Qubes_4.2_A-update_20240425043702.log.txt'
                                                   }
Apr 25 20:26:17 ws-ci-bastion ws-ci-runner[58966]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-25-201640344998-bbc72e59ad497dccaabaed986e3ab1475071e719-Qubes_4.2_A-update_20240425043702.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-25-201640344998-bbc72e59ad497dccaabaed986e3ab1475071e719-Qubes_4.2_A-update_20240425043702.log.txt'
                                                   }
Apr 25 20:29:23 ws-ci-bastion ws-ci-runner[58671]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-25-192336452267-b003ae8edc73120326452d80255fc4989f341840-Qubes_4.2_A-update_20240425043702.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-25-192336452267-b003ae8edc73120326452d80255fc4989f341840-Qubes_4.2_A-update_20240425043702.log.txt'
                                                   }
Apr 27 06:40:15 ws-ci-bastion ws-ci-runner[80311]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                      dynamicType = <unset>,
                                                      dynamicProperty = (vmodl.DynamicProperty) [],
                                                      msg = 'File /home/user/2024-04-27-063004359652-f65d3795971be6763a6b65272f144fcc76ff9e53-Qubes_4.2_A-update_20240427050925.log.txt was not found',
                                                      faultCause = <unset>,
                                                      faultMessage = (vmodl.LocalizableMessage) [],
                                                      file = '/home/user/2024-04-27-063004359652-f65d3795971be6763a6b65272f144fcc76ff9e53-Qubes_4.2_A-update_20240427050925.log.txt'
                                                   }
Apr 30 16:31:14 ws-ci-bastion ws-ci-runner[114544]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                       dynamicType = <unset>,
                                                       dynamicProperty = (vmodl.DynamicProperty) [],
                                                       msg = 'File /home/user/2024-04-30-162835707878-9a8bfe8ba389708dd559b389bead4ea0f3d36fe6-Qubes_4.2_A-update_20240430043846.log.txt was not found',
                                                       faultCause = <unset>,
                                                       faultMessage = (vmodl.LocalizableMessage) [],
                                                       file = '/home/user/2024-04-30-162835707878-9a8bfe8ba389708dd559b389bead4ea0f3d36fe6-Qubes_4.2_A-update_20240430043846.log.txt'
                                                    }
Apr 30 17:29:04 ws-ci-bastion ws-ci-runner[114848]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                       dynamicType = <unset>,
                                                       dynamicProperty = (vmodl.DynamicProperty) [],
                                                       msg = 'File /home/user/2024-04-30-172614439415-962f4df81ec34b433eaa2a721b6bbf3b2d185cf2-Qubes_4.2_B-update_20240430050321.log.txt was not found',
                                                       faultCause = <unset>,
                                                       faultMessage = (vmodl.LocalizableMessage) [],
                                                       file = '/home/user/2024-04-30-172614439415-962f4df81ec34b433eaa2a721b6bbf3b2d185cf2-Qubes_4.2_B-update_20240430050321.log.txt'
                                                    }
May 01 17:11:42 ws-ci-bastion ws-ci-runner[124321]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                       dynamicType = <unset>,
                                                       dynamicProperty = (vmodl.DynamicProperty) [],
                                                       msg = 'File /home/user/2024-05-01-170904406909-af745439da1352f2437dc010d50411432089d417-Qubes_4.2_A-update_20240501043530.log.txt was not found',
                                                       faultCause = <unset>,
                                                       faultMessage = (vmodl.LocalizableMessage) [],
                                                       file = '/home/user/2024-05-01-170904406909-af745439da1352f2437dc010d50411432089d417-Qubes_4.2_A-update_20240501043530.log.txt'
                                                    }
May 03 18:33:05 ws-ci-bastion ws-ci-runner[145282]: Error occurred during execution: (vim.fault.FileNotFound) {
                                                       dynamicType = <unset>,
                                                       dynamicProperty = (vmodl.DynamicProperty) [],
                                                       msg = 'File /home/user/2024-05-03-182742943929-9ee06867c586739cf357777e2c49d0a577f84bbb-Qubes_4.2_C-update_20240503045634.log.txt was not found',
                                                       faultCause = <unset>,
                                                       faultMessage = (vmodl.LocalizableMessage) [],
                                                       file = '/home/user/2024-05-03-182742943929-9ee06867c586739cf357777e2c49d0a577f84bbb-Qubes_4.2_C-update_20240503045634.log.txt'
                                                    }

sudo journalctl | grep -B10 -A10 "vim.fault.FileNotFound" provides some more context usually.

[mig5]

The log file gets created as part of the construct the moment that dom0's runner.py is executed (via RPC from the sd-dev in begin.py).

This therefore means the sd-dev's begin.py probably didn't even get as far as triggering the RPC policy (or the RPC request failed somehow).

In other words, the 'File Not Found' is merely the naive attempt to fetch the log after the execution finished, and if it didn't exist, it means it probably never even ran runner.py on the dom0.

The most likely scenario is that something before that step failed. The main steps in begin.py that precede the call to the RPC policy, involve:

1. Cloning the git repo and checking out that commit
   https://github.com/freedomofpress/securedrop-workstation-ci/blob/main/sd-dev/bin/begin.py#L50-L62

2. Commit status POST to Github via the API saying the build is pending
   https://github.com/freedomofpress/securedrop-workstation-ci/blob/main/sd-dev/bin/begin.py#L77-L86

My gut instinct tells me it's probably an intermittent failure connecting to Github in one of those two steps. The journalctl on the sd-dev would probably tell us more (or, say, the absence of the cloned repo in the sd-dev VM as a tell-tale sign that the clone failed)

We can hopefully reduce the chance of network interference by reducing the number of network requests we have to make:

a) Moving the commit status stuff to the webhook, so it at least happens much earlier, and maybe even just the one commit status 'running' rather than 'pending', to reduce the chance of a failure (#63)

b) Perhaps we can somehow copy the codebase into dom0/sd-dev rather than have sd-dev clone it again, since we already clone it on the bastion to inspect the yaml file to learn the Qubes version. I'm not sure how hard it is to copy a folder and its contents via the VMware API, but we could certainly just tarball it up and extract on the other side.

But this is all just a theory.. unfortunately, these things seem to happen when I'm not around, and by the time I am, it's too late to check the Qubes VM to see if things like the cloned git repo exist in the sd-dev VM, as it'll have been restored from snapshot for another CI run :(