Viam - Logging in Python?

[danic85]

In the modular biped project we have a logging tool that uses pubsub to subscribe to various log requests.

The tool utilises the python logging module, but it would be good to have the option to interface with the viam logging tool instead.

I see an example to configure logging, but in the python there is no example to output:

# In your import block, import the logging package:
from viam.logging import getLogger

# Before your first class or function, define the LOGGER variable:
LOGGER = getLogger(__name__)

What is the python equivalent of c.logger.Infof("performing some function with a=%v",a) and similar, shown in the go example.

Then following that, would it make sense me creating a module to log from pubsub, based on the example I have already? Is there something on the roadmap around improved logging that would supersede this?

Very broadly I'd like to enable:

• Publish event to log info, error, etc to the viam log.
• Enable toggling of module specific verbose logging, to reduce noise in the log but allow detailed debugging if needed
• Toggle logging to file (with rotation) at a feature level

[danic85]

@mcvella

[mcvella]

Here's a PR to add loglevel info to our docs: viamrobotics/docs#2377
Loglevels per resource is under development, you can follow here: https://viam.atlassian.net/browse/RSDK-4963
Tell me more about why you'd want to log to a file per feature...

As for a modules that use pubsub for logs, definitely an interesting idea, I wonder if we should have a conversation in more detail around how you're using pubsub overall and if there might be another pattern that would work and is more Viam-native.

[danic85]

Great to see your Jira is accessible externally 👏

Tell me more about why you'd want to log to a file per feature...

It's more like I want to log to a file, and when I do I want to specify which features are logging (or at least how verbose the logging is for each feature).

I'll write up some notes one the pubsub side of things soon ;)

[mcvella]

It's more like I want to log to a file, and when I do I want to specify which features are logging (or at least how verbose the logging is for each feature).

OK, so I think our current eng effort will cover this!

[danic85]

@mcvella I have tried adding logging to a few different places that are referenced by a process, and finally added it directly to the process but I'm not seeing any debug output.

I know the process is being executed because the robot starts 'behaving', but nothing comes through on the logs.

I do get logs from a simple module I created which is running in parallel, but that output is the run.sh echo statement.

I feel like this means I haven't configured the process correctly. Can you spot anything out of place?

UPDATE: Aside from the debug logging, if I cause the process to fail deliberately, it will show the below error but not provide any additional context:
2024-01-13T20:58:25.034Z   error robot_server   impl/resource_manager.go:982   error while adding process; skipping   process main   error error running process "python3": exit status 1

But running the script directly via SSH will show the error message and traceback. So it looks like the viam server is suppressing some error logging, which is the opposite of what I want 😅

These are the first challenges around the debugging issues we discussed, once I have logging working I will hopefully find the rest of the integration goes more quickly.

Guide for reference

[mcvella]

Try using a different loglevel other than debug - by default viam-server runs at info level.
To run viam-server at debug level, you can start it manually with the -debug flag.

[danic85]

Thanks @mcvella - I added an info and a warn to the process script, but they're not visible in the logs on the app.

If i add an error The process does appear to exit (with 2024-01-16T20:37:43.399Z   error robot_server   impl/resource_manager.go:982   error while adding process; skipping   process main   error error running process "python3": signal: killed), but the message isn't displayed in the logs.

I also ran in debug mode sudo viam-server -config /etc/viam.json -debug but the debug output from the process wasn't displayed either (I did see others, so I could see it was running in the right mode).

Anything else I can try?

[mcvella]

Sounds like maybe the process is exiting before it even logs; can you show me your process config?

[danic85]

In that case let me create a smaller process with just the basics and try that first. I'll get back to you.

…

________________________________ From: Matt Vella ***@***.***> Sent: Tuesday, January 16, 2024 8:52:23 PM To: makerforgetech/modular-biped ***@***.***> Cc: Dan Nicholson ***@***.***>; Author ***@***.***> Subject: Re: [makerforgetech/modular-biped] Viam - Logging in Python? (Discussion #74) Sounds like maybe the process is exiting before it even logs; can you show me your process config? — Reply to this email directly, view it on GitHub<#74 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ABSHFZGTFV4CIYP5PKPJBXLYO3SAPAVCNFSM6AAAAABBTREFHCVHI2DSMVQWIX3LMV43SRDJONRXK43TNFXW4Q3PNVWWK3TUHM4DCNBZGE2TA>. You are receiving this because you authored the thread.Message ID: ***@***.***>

[danic85]

Ok @mcvella I've created a simple test process and I can see logging there so I'll break down the main script and see where it might be failing.

I'll update in a day or so after i've taken a look in more detail.

Thanks for your help!

[danic85]

Just a quick update on this @mcvella now I've had a chance to double check, it turns out it was running the whole time, but seems that the custom logging doesn't output if I have the checkbox on the process called 'Execute once' checked. That was the problem in my initial testing and as soon as I disabled that it worked perfectly.

As another small piece of feedback: the log is quite difficult to scan through, especially on a lower resolution. My main monitor isn't so bad but a laptop resolution that causes word wrapping makes it very difficult to scan the logs for the issues, especially since a multi-line message shows as multiple log entries with a timestamp etc.
Improving the layout and grouping of messages and even allowing us to filter out certain text elements (datetime, pexec etc) would add value to using the Viam logger in preference to tailing a log file or similar approaches.

For an example around filtering text, this is one line from the log:
2024-01-18T23:21:28.655Z   info robot_server.process.main_python3.StdOut   pexec/managed_process.go:244   \_ 2024-01-18 23:21:28,655 �[33;36mINFO�[0m modules.logwrapper (logwrapper.py:43) [TEMP] 57.1
And here's what I actually care about:
[TEMP] 57.1

😆

 

[mcvella]

Noted! We've brought this up internally before, I'll make sure to surface it to the product team.

[mcvella]

https://viam.atlassian.net/browse/APP-3690

[danic85]

You don't have access to this issue, just FYI. But don't worry, it's not a problem.