improve logging for resource allocation
Log on level 'log', more clearly show whether it's for reservation or actual
use, show the origin that is asking for them.
Change-Id: I3b78c7bdcaec90943900343c878099160f8d2f64
diff --git a/selftest/resource_test.ok b/selftest/resource_test.ok
index 764dfc1..db6a8bf 100644
--- a/selftest/resource_test.ok
+++ b/selftest/resource_test.ok
@@ -155,15 +155,15 @@
*** end: all resources
- request some resources
---- (want='arfcn'): DBG: Looking for 2 x arfcn , candidates: 10
---- (want='arfcn'): DBG: Picked - _hash: e620569450f8259b3f0212ec19c285dd07df063c
+--- testowner: Reserving 2 x arfcn (candidates: 10)
+--- testowner: DBG: Picked - _hash: e620569450f8259b3f0212ec19c285dd07df063c
arfcn: '512'
band: GSM-1800
- _hash: 022621e513c5a5bf33b77430a1e9c886be676fa1
arfcn: '514'
band: GSM-1800
---- (want='bts'): DBG: Looking for 2 x bts , candidates: 3
---- (want='bts'): DBG: Picked - _hash: 07d9c8aaa940b674efcbbabdd69f58a6ce4e94f9
+--- testowner: Reserving 2 x bts (candidates: 3)
+--- testowner: DBG: Picked - _hash: 07d9c8aaa940b674efcbbabdd69f58a6ce4e94f9
addr: 10.42.42.114
band: GSM-1800
ipa_unit_id: '1'
@@ -177,8 +177,8 @@
trx_list:
- hw_addr: 00:0c:90:32:b5:8a
type: oct
---- (want='modem'): DBG: Looking for 2 x modem , candidates: 16
---- (want='modem'): DBG: Picked - _hash: 19c69e45aa090fb511446bd00797690aa82ff52f
+--- testowner: Reserving 2 x modem (candidates: 16)
+--- testowner: DBG: Picked - _hash: 19c69e45aa090fb511446bd00797690aa82ff52f
imsi: '901700000007801'
ki: D620F48487B1B782DA55DF6717F08FF9
label: m7801
@@ -188,8 +188,8 @@
ki: 47FDB2D55CE6A10A85ABDAD034A5B7B3
label: m7802
path: /wavecom_1
---- (want='nitb_iface'): DBG: Looking for 1 x nitb_iface , candidates: 3
---- (want='nitb_iface'): DBG: Picked - _hash: cde1debf28f07f94f92c761b4b7c6bf35785ced4
+--- testowner: Reserving 1 x nitb_iface (candidates: 3)
+--- testowner: DBG: Picked - _hash: cde1debf28f07f94f92c761b4b7c6bf35785ced4
addr: 10.42.42.1
~~~ currently reserved:
arfcn:
diff --git a/selftest/suite_test.ok b/selftest/suite_test.ok
index 0321b26..b20bdc5 100644
--- a/selftest/suite_test.ok
+++ b/selftest/suite_test.ok
@@ -28,15 +28,16 @@
tst test_suite: reserving resources...
tst test_suite: DBG: {combining='resources'} [test_suite↪test_suite]
tst test_suite: DBG: {definition_conf={bts=[{'times': '1'}], modem=[{'times': '2'}], nitb_iface=[{'times': '1'}]}} [test_suite↪(combining_scenarios='resources')↪test_suite]
---- (want='bts'): DBG: Looking for 1 x bts , candidates: 3
---- (want='bts'): DBG: Picked - _hash: 07d9c8aaa940b674efcbbabdd69f58a6ce4e94f9
+tst test_suite: Reserving 1 x bts (candidates: 3) [test_suite↪test_suite]
+tst test_suite: DBG: Picked - _hash: 07d9c8aaa940b674efcbbabdd69f58a6ce4e94f9
addr: 10.42.42.114
band: GSM-1800
ipa_unit_id: '1'
label: sysmoBTS 1002
type: sysmo
---- (want='modem'): DBG: Looking for 2 x modem , candidates: 16
---- (want='modem'): DBG: Picked - _hash: 19c69e45aa090fb511446bd00797690aa82ff52f
+ [test_suite↪test_suite]
+tst test_suite: Reserving 2 x modem (candidates: 16) [test_suite↪test_suite]
+tst test_suite: DBG: Picked - _hash: 19c69e45aa090fb511446bd00797690aa82ff52f
imsi: '901700000007801'
ki: D620F48487B1B782DA55DF6717F08FF9
label: m7801
@@ -46,9 +47,11 @@
ki: 47FDB2D55CE6A10A85ABDAD034A5B7B3
label: m7802
path: /wavecom_1
---- (want='nitb_iface'): DBG: Looking for 1 x nitb_iface , candidates: 3
---- (want='nitb_iface'): DBG: Picked - _hash: cde1debf28f07f94f92c761b4b7c6bf35785ced4
+ [test_suite↪test_suite]
+tst test_suite: Reserving 1 x nitb_iface (candidates: 3) [test_suite↪test_suite]
+tst test_suite: DBG: Picked - _hash: cde1debf28f07f94f92c761b4b7c6bf35785ced4
addr: 10.42.42.1
+ [test_suite↪test_suite]
tst hello_world.py: START [test_suite↪hello_world.py]
tst hello_world.py:3: hello world [test_suite↪hello_world.py:3]
tst hello_world.py:4: I am 'test_suite' / 'hello_world.py:4' [test_suite↪hello_world.py:4]
diff --git a/src/osmo_gsm_tester/resource.py b/src/osmo_gsm_tester/resource.py
index 699b465..2a64772 100644
--- a/src/osmo_gsm_tester/resource.py
+++ b/src/osmo_gsm_tester/resource.py
@@ -148,7 +148,7 @@
with self.state_dir.lock(origin_id):
rrfile_path = self.state_dir.mk_parentdir(RESERVED_RESOURCES_FILE)
reserved = Resources(config.read(rrfile_path, if_missing_return={}))
- to_be_reserved = self.all_resources.without(reserved).find(want)
+ to_be_reserved = self.all_resources.without(reserved).find(origin, want)
to_be_reserved.mark_reserved_by(origin_id)
@@ -270,7 +270,7 @@
def without(self, reserved):
return Resources(self).drop(reserved)
- def find(self, want, skip_if_marked=None, do_copy=True, raise_if_missing=True):
+ def find(self, for_origin, want, skip_if_marked=None, do_copy=True, raise_if_missing=True, log_label='Reserving'):
'''
Pass a dict of resource requirements, e.g.:
want = {
@@ -297,13 +297,12 @@
'''
matches = {}
for key, want_list in sorted(want.items()): # sorted for deterministic test results
- # here we have a resource of a given type, e.g. 'bts', with a list
- # containing as many BTSes as the caller wants to reserve/use. Each
- # list item contains specifics for the particular BTS.
- with log.Origin(want=key):
+ # here we have a resource of a given type, e.g. 'bts', with a list
+ # containing as many BTSes as the caller wants to reserve/use. Each
+ # list item contains specifics for the particular BTS.
my_list = self.get(key)
- log.dbg(None, None, 'Looking for', len(want_list), 'x', key, ', candidates:', len(my_list))
+ for_origin.log(log_label, len(want_list), 'x', key, '(candidates: %d)'%len(my_list))
# Try to avoid a less constrained item snatching away a resource
# from a more detailed constrained requirement.
@@ -341,7 +340,7 @@
# figure out who gets what
solution = solve(all_matches)
picked = [ my_list[i] for i in solution if i is not None ]
- log.dbg(None, None, 'Picked', config.tostr(picked))
+ for_origin.dbg('Picked', config.tostr(picked))
matches[key] = picked
return Resources(matches, do_copy=do_copy)
@@ -459,7 +458,9 @@
specifics = {}
self.dbg('requesting use of', kind, specifics=specifics)
want = { kind: [specifics] }
- available_dict = self.reserved.find(want, skip_if_marked=USED_KEY, do_copy=False, raise_if_missing=False)
+ available_dict = self.reserved.find(self.origin, want, skip_if_marked=USED_KEY,
+ do_copy=False, raise_if_missing=False,
+ log_label='Using')
available = available_dict.get(kind)
self.dbg(available=len(available))
if not available: