add logging of reserve and release events..

bitelab/__init__.py

@@ -58,6 +58,7 @@ import sqlite3
 import subprocess
 import sys
 import tempfile
+import time
 import ucl
 import unittest
 import urllib
@@ -73,6 +74,26 @@ def new_parse_socket_addr(domain, addr):
 
 tcp_server.parse_socket_addr = new_parse_socket_addr
 
+async def log_event(tag, board=None, user=None, extra={}):
+	info = extra.copy()
+	info['event'] = tag
+
+	if board is not None:
+		info['board_name'] = board.name
+	else:
+		info.pop('board_name', None)
+
+	if user is not None:
+		info['user'] = user
+	else:
+		info.pop('user', None)
+
+	t = time.time()
+	info['date'] = time.strftime('%Y-%m-%dT%H:%M:%S', time.gmtime(t)) + \
+	    '.%03dZ' % (int((t * 1000) % 1000),)
+
+	logging.info(json.dumps(info))
+
 class EtherIface(DefROAttribute):
 	defattrname = 'eiface'
 
@@ -411,6 +432,8 @@ async def reserve_board(board_id_or_class,
 
 		await brd.activate()
 
+		await log_event('reserve', user=user, board=brd)
+
 	await brd.update()
 
 	return brd
@@ -423,6 +446,9 @@ async def release_board(board_id, user: str = Depends(lookup_user),
 	brd = brdmgr.boards[board_id]
 
 	async with brd.lock:
+		# XXX - how to handle a release error?
+		await log_event('release', user=user, board=brd)
+
 		try:
 			brduser = await data.BoardStatus.objects.get(board=board_id)
 			if user != brduser.user:
@@ -660,11 +686,12 @@ class TestBiteLab(unittest.IsolatedAsyncioTestCase):
 		# and that the error got logged
 		le.assert_called_with('release script failure: board: \'cora-1\', ret: 1, stderr: b\'error\'')
 
+	@patch('bitelab.log_event')
 	@patch('bitelab.BoardImpl.deactivate')
 	@patch('bitelab.BoardImpl.activate')
 	@patch('asyncio.create_subprocess_exec')
 	@patch('bitelab.snmp.snmpget')
-	async def test_board_reserve_release(self, sg, cse, biact, bideact):
+	async def test_board_reserve_release(self, sg, cse, biact, bideact, le):
 		# that when releasing a board that is not yet reserved
 		res = await self.client.post('/board/cora-1/release',
 		    auth=BiteAuth('anotherlongapikey'))
@@ -737,6 +764,10 @@ class TestBiteLab(unittest.IsolatedAsyncioTestCase):
 		# and that the board was activated
 		biact.assert_called()
 
+		# and that log_event was called properly
+		le.assert_called_with('reserve', user='foo',
+		    board=self.brdmgr.boards['cora-1'])
+
 		# that another user reserving the board
 		res = await self.client.post('/board/cora-1/reserve',
 		    auth=BiteAuth('anotherlongapikey'))
@@ -781,6 +812,10 @@ class TestBiteLab(unittest.IsolatedAsyncioTestCase):
 		}
 		self.assertEqual(res.json(), info)
 
+		# and that log_event was called properly
+		le.assert_called_with('release', user='foo',
+		    board=self.brdmgr.boards['cora-1'])
+
 		env = os.environ.copy()
 		env['ip'] = brdinfo['attrs']['ip']
 		env['iface'] = brdinfo['attrs']['iface']
@@ -950,6 +985,49 @@ class TestBoardImpl(unittest.IsolatedAsyncioTestCase):
 
 		opt.deactivate.assert_called_with(brd)
 
+class TestLogEvent(unittest.IsolatedAsyncioTestCase):
+	@patch('time.time')
+	@patch('logging.info')
+	async def test_log_event(self, li, tt):
+		tag = 'eslkjdf'
+		user = 'weoijsdfkj'
+		brdname = 'woied'
+		extra = dict(something=2323, someelse='asdlfkj')
+		brd = BoardImpl(brdname, {}, [])
+
+		tt.return_value = 1607650392.384
+
+		await log_event(tag, user=user, board=brd, extra=extra)
+
+		res = dict(event=tag, board_name=brdname, user=user,
+		    date='2020-12-11T01:33:12.384Z', **extra)
+
+		# that log_event logs the correct data
+		self.assertEqual(len(li.call_args[0]), 1)
+
+		# that the logged data can be parsed as json, and results
+		# in the correct object
+		self.assertEqual(json.loads(li.call_args[0][0]), res)
+
+		tt.return_value = 1607650393.289
+
+		# that log_event handles no board/user
+		await log_event(tag)
+
+		res = json.dumps(dict(event=tag,
+		    date='2020-12-11T01:33:13.289Z'))
+
+		li.assert_called_with(res)
+
+		# that log_event doesn't allow board/user from extra
+		await log_event(tag, extra=dict(board_name='sldkfj',
+		    user='sod'))
+
+		res = json.dumps(dict(event=tag,
+		    date='2020-12-11T01:33:13.289Z'))
+
+		li.assert_called_with(res)
+
 class TestAttrs(unittest.IsolatedAsyncioTestCase):
 	@patch('asyncio.create_subprocess_exec')
 	async def test_serialconsole(self, cse):

bitelab/testing.py

@@ -30,5 +30,5 @@
 
 from .snmp import TestSNMPPower, TestSNMPWrapper
 from .data import TestDatabase
-from . import TestBiteLab, TestUnhashLRU, TestAttrs, TestBoardImpl
+from . import TestBiteLab, TestUnhashLRU, TestAttrs, TestBoardImpl, TestLogEvent
 from .__main__ import TestClient