mavsdk_server errors not shown to users

[EricPedley]

I was using mavsdk to try communicating with PX4 SITL today and also had mavros running, which made mavsdk_server crash on launch because the udp connection I was trying was already in use. It was hard to debug because when system.py runs mavsdk_server as a subprocess, the stdout is redirected to a logging thread which logs everything at debug level, which is not shown to users (and for new users like me I don't even know how to get it to show me the debug output). From the user's perspective, the call to connect just hangs forever. This error also happens if you input a malformed URL like udp://14540 (which is missing a colon before the port number), it'll just hang forever instead of giving the user a useful error message.

[JonasVautherin]

Wasn't it already addressed by this PR? Would you mind trying it and letting me know if that solves your problem?

I had tried it with an example script here.

[EricPedley]

Tried that and for some reason it still doesn't log the error messages. I'm running this program to test out the logging:

import asyncio
from mavsdk import System
import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)

async def main():
    drone = System()
    print("awaiting connection")
    await drone.connect(system_address="udp://14550") # should give an error message about bad connection URL
    print("done connecting")
    version_info = await drone.info.get_version()
    print(version_info)

asyncio.run(main())

The output with mavsdk-python on main looks like this:

And with the changes in my PR (#586) it looks like this:

I think that something is broken with the logging thread for mavsdk_server because it should be displaying the stuff when I turn on debug logging, but it doesn't unless I completely remove the debug logging thread from the program. Or it might be something about my local setup that's preventing the logging because it looks like it should work correctly.
Either way, I feel like #370 isn't sufficient here because the output from mavsdk_server seems important enough to always log by default, but currently for it to be shown the user needs to turn on debug-level logging.

[JonasVautherin]

I think that something is broken with the logging thread for mavsdk_server because it should be displaying the stuff when I turn on debug logging

Yes it should, I remember it was working for me 🤔. Maybe it got broken somehow. Would you be able to look into it? I'll try to reproduce it when I have time 👍.

Either way, I feel like #370 isn't sufficient here because the output from mavsdk_server seems important enough to always log by default, but currently for it to be shown the user needs to turn on debug-level logging.

Hmm I think I kindly disagree 🙈. I think it's nice to give the choice to users. However we could improve the documentation (e.g. by adding the logging to the examples) to make it more obvious how to do it.

[EricPedley]

This is extremely cursed, but I realized that the mavsdk process actually doesn't actually produce the output I'm looking for at all when piped. Could be a quirk of my computer or a problem with the mavsdk server itself. However, I stand by my original point that the logging should work opposite how it does currently. It should be on by default, and users should have to take action to turn it off. The downside of keeping logging as it is currently is that it prevents users from immediately seeing the cause of some bugs, while the downside of switching the default is that users see more output in their terminal. I think the former (making it harder to diagnose bugs) is a much worse problem than extra verbose output that can be toggled off.

[EricPedley]

Just had this problem again because mavsdk now requires you to use "udpin" instead of "udp" but the error message is suppressed and it just looks like it's hanging forever trying to connect

[EricPedley]

setting these two values to None un-suppresses the logging from mavsdk and let me figure out what was going wrong.

[julianoes]

Oh, that's a good fix. Can you make a pull request to fix it?