Implement Logging
Our Agent contains several native Python print statements. While these do end
up in the logs it is better to use the logging system within OCS. We do so by
adding a log attribute to the Agent class. Focusing on just the addition of
self.log
this looks like:
class BarebonesAgent:
"""Barebone Agent demonstrating writing an Agent from scratch.
Attributes:
log (txaio.tx.Logger): Logger object used to log events within the
Agent.
"""
def __init__(self, agent):
self.agent = agent
self.log = agent.log
self._count = False
Within the if __name__ == '__main__':
block we need to do some additional
configuration, including setting the log level via environment variable:
# For logging
txaio.use_twisted()
LOG = txaio.make_logger()
# Start logging
txaio.start_logging(level=environ.get("LOGLEVEL", "info"))
Now, any print()
statement can become a self.log.info()
statement.
There are additional levels to logging, including “debug”. For more info on
logging see Logging.
Agent Code
Our Agent in full now looks like this:
import time
import txaio
from os import environ
from ocs import ocs_agent, site_config
class BarebonesAgent:
"""Barebone Agent demonstrating writing an Agent from scratch.
This Agent is meant to be an example for Agent development, and provides a
clean starting point when developing a new Agent.
Parameters:
agent (OCSAgent): OCSAgent object from :func:`ocs.ocs_agent.init_site_agent`.
Attributes:
agent (OCSAgent): OCSAgent object from :func:`ocs.ocs_agent.init_site_agent`.
log (txaio.tx.Logger): Logger object used to log events within the
Agent.
lock (TimeoutLock): TimeoutLock object used to prevent simultaneous
commands being sent to hardware.
_count (bool): Internal tracking of whether the Agent should be
counting or not. This is used to exit the Process loop by changing
it to False via the count.stop() command. Your Agent won't use this
exact attribute, but might have a similar one.
"""
def __init__(self, agent):
self.agent = agent
self.log = agent.log
self._count = False
def count(self, session, params):
"""count(test_mode=False)
**Process** - Count up from 0.
The count will restart if the process is stopped and restarted.
Notes:
The most recent value is stored in the session data object in the
format::
>>> response.session['data']
{"value": 0,
"timestamp":1600448753.9288929}
"""
# Initialize the counter
self._count=True
counter = 0
self.log.info("Starting the count!")
# Main process loop
while self.count:
counter += 1
self.log.debug(f"{counter}! Ah! Ah! Ah!")
session.data = {"value": counter,
"timestamp": time.time()}
time.sleep(1)
return True, 'Acquisition exited cleanly.'
def _stop_count(self, session, params):
"""Stop monitoring the turbo output."""
if self.count:
self.count = False
return True, 'requested to stop taking data.'
else:
return False, 'count is not currently running'
@ocs_agent.param('text', default='hello world', type=str)
def print(self, session, params):
"""print(text='hello world')
**Task** - Print some text passed to a Task.
Args:
text (str): Text to print out. Defaults to 'hello world'.
Notes:
The session data will be updated with the text::
>>> response.session['data']
{'text': 'hello world',
'last_updated': 1660249321.8729222}
"""
# Log the text provided to the Agent logs
self.log.info(f"{params['text']}")
# Store the text provided in session.data
session.data = {'text': params['text'],
'last_updated': time.time()}
# bool, 'descriptive text message'
# True if task succeeds, False if not
return True, 'Printed text to logs'
def main(args=None):
# For logging
txaio.use_twisted()
LOG = txaio.make_logger()
# Start logging
txaio.start_logging(level=environ.get("LOGLEVEL", "info"))
args = site_config.parse_args(agent_class='BarebonesAgent', args=args)
agent, runner = ocs_agent.init_site_agent(args)
barebone = BarebonesAgent(agent)
agent.register_process(
'count',
barebone.count,
barebone._stop_count)
agent.register_task('print', barebone.print)
runner.run(agent, auto_reconnect=True)
if __name__ == '__main__':
main()
Running the Agent
If we run the Agent now we will notice that the self.log.debug
statements
no longer print by default to the logs (they would if LOGLEVEL=debug
), but
self.log.info
statements are still printed.
Client commands:
>>> from ocs.ocs_client import OCSClient
>>> client = OCSClient('barebones1')
>>> client.count.start()
OCSReply: ERROR : Operation "count" already in progress.
count[session=0]; status=running for 6.5 s
messages (2 of 2):
1658884651.313 Status is now "starting".
1658884651.314 Status is now "running".
other keys in .session: op_code, data
>>> client.count.status().session['data']
{'value': 15, 'timestamp': 1658884665.329796}
>>> client.count.stop()
OCSReply: OK : Requested stop on process "count".
count[session=0]; status=running for 18.9 s
messages (2 of 2):
1658884651.313 Status is now "starting".
1658884651.314 Status is now "running".
other keys in .session: op_code, data
Agent logs:
2022-07-27T01:17:31+0000 start called for count
2022-07-27T01:17:31+0000 count:0 Status is now "starting".
2022-07-27T01:17:31+0000 Starting the count!
2022-07-27T01:17:31+0000 count:0 Status is now "running".
2022-07-27T01:17:37+0000 start called for count
2022-07-27T01:17:50+0000 count:0 Acquisition exited cleanly.
2022-07-27T01:17:50+0000 count:0 Status is now "done".
Next, we will learn about operation locking, allowing only a single task or process to run at once.