Log exit code and command line on spawn failures#224
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #224 +/- ##
==========================================
+ Coverage 78.96% 80.91% +1.95%
==========================================
Files 55 58 +3
Lines 10544 10817 +273
==========================================
+ Hits 8326 8753 +427
+ Misses 2218 2064 -154 ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
| } | ||
| if (exit_code != 0) { | ||
| LOG(ERROR, "failed to spawn process"); | ||
| LOG(ERROR, "failed to spawn process %d, exited with %d", pid, exit_code); |
There was a problem hiding this comment.
When execute_parsed_qubes_rpc_command() fails, the process wasn't started, so pid isn't really initialized - this basically logs random garbage from stack...
As for exit_code here, from what I see it can be either QREXEC_EXIT_PROBLEM (125) or QREXEC_EXIT_SERVICE_NOT_FOUND (127), not any more details. And I think most issues that could use some more info are about just exit code 125.
OTOH, what might be more useful is to log what command failed, to ease searching the logs. Note most error paths leading to returning an error here already log the reason to stderr, so, having having command/service name here would make it a bit easier to find the previous line with more info.
|
PipelineRetryFailed |
2 similar comments
|
PipelineRetryFailed |
|
PipelineRetryFailed |
|
Marek, some weird failure: https://gitlab.com/QubesOS/qubes-core-qrexec/-/jobs/14147342413 _______ TestAgentExecQubesRpc.test_exec_service_with_invalid_config_path _______
self = <qrexec.tests.socket.agent.TestAgentExecQubesRpc testMethod=test_exec_service_with_invalid_config_path>
def test_exec_service_with_invalid_config_path(self):
util.make_executable_service(
self.tempdir,
"rpc",
"qubes.Service",
"""\
#!/bin/sh
echo "arg: $1, remote domain: $QREXEC_REMOTE_DOMAIN"
""",
)
config_path = os.path.join(self.tempdir, "rpc-config")
os.rmdir(config_path)
os.symlink("/dev/null/doesnotexist", config_path)
> self._test_exec_service_fail()
qrexec/tests/socket/agent.py:659:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
qrexec/tests/socket/agent.py:616: in _test_exec_service_fail
self.assertListEqual(
E AssertionError: Lists differ: [] != [(401, b''), (402, b''), (403, b'}\x00\x00\x00')]
E
E Second list contains 3 additional elements.
E First extra element 0:
E (401, b'')
E
E - []
E + [(401, b''), (402, b''), (403, b'}\x00\x00\x00')]
----------------------------- Captured stderr call -----------------------------
2026-04-29 12:16:37.017 qrexec-agent[2184]: exec.c:437:find_file: stat/lstat(/tmp/tmppsnv8acm/rpc-config/qubes.Service+arg): Not a directory
2026-04-29 12:16:37.017 qrexec-agent[2184]: qrexec-agent.c:606:handle_server_exec_request_init: Could not load config for command gitlab-runner:QUBESRPC qubes.Service+arg domX |
This is expected given the test name. But it should send final packets. The test passes on main, so I think this PR introduces the regression. Maybe it crashes before sending it? Looking at the code, one explanation could be |
qubes-core-qrexec/agent/qrexec-agent.c Line 688 in f6e44ea Here the |
OpenQA test summaryComplete test suite and dependencies: https://openqa.qubes-os.org/tests/overview?distri=qubesos&version=4.3&build=2026050811-devel&flavor=pull-requests Test run included the following:
New failures, excluding unstableCompared to: https://openqa.qubes-os.org/tests/overview?distri=qubesos&version=4.3&build=2026050504-devel&flavor=update
Failed tests18 failures
Fixed failuresCompared to: https://openqa.qubes-os.org/tests/176874#dependencies 32 fixed
Unstable testsDetailsPerformance TestsPerformance degradation:30 performance degradations
Remaining performance tests:81 tests
|
In that case ( So, maybe instead of passing along not very useful string, simply handle NULL cmd in that error message with some placeholder, like |
I think it is useful or am I misunderstanding something. Capturing stderr with
I wouldn't say I like the current solution over passing In the case of invalid configuration file, it might make sense to free just invalid variables instead of destroying the whole struct. Would you prefer that I make an attempt at that? |
Right, and in this case such information is useful (and also my proposed message is wrong). But it's already logged in a separate message, no? So, maybe to avoid confusion, rename the parameter to something like |
"failed to spawn process" for daemon and agent
So in all cases where I prefer how the daemon logging is done in this case, it only prints the full cmdline at the end. I made some modifications, see what you think (using with cmdline at the end
Or if you prefer not passing the variable just for logging, as the "Cannot/Could load service configuration" already has access to the cmdline. without passing the variable downstream
|
|
I noticed I didn't add a question mark, but the post above was meant to ask which option you prefer based on provided logs. |
With the name adjusted, it would be better with, especially since it just about MSG_SERVICE_CONNECT, but also normal service calls. Technically the information is there already, but it may be not easy to find which one is about which call (you need to look at PID in the journal message). |
Sometimes the PID changes: 2069764 and 2069766. |
Done. |
For: QubesOS/qubes-issues#10740
Logging this information makes it easier to grep on huge logs.