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
This commit is contained in:
Neels Hofmeyr 2017-05-07 01:16:07 +02:00
parent 56b3d7e685
commit cccbe5987d
3 changed files with 27 additions and 23 deletions

View File

@ -155,15 +155,15 @@ cnf -: DBG: Found path state_dir as [PATH]/selftest/conf/test_work/state_dir
*** 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 @@ cnf -: DBG: Found path state_dir as [PATH]/selftest/conf/test_work/state_dir
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 @@ cnf -: DBG: Found path state_dir as [PATH]/selftest/conf/test_work/state_dir
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:

View File

@ -28,15 +28,16 @@ tst test_suite: Suite run start
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 @@ tst test_suite: DBG: {definition_conf={bts=[{'times': '1'}], modem=[{'times': '2
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]

View File

@ -148,7 +148,7 @@ class ResourcesPool(log.Origin):
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 @@ class Resources(dict):
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 @@ class Resources(dict):
'''
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 @@ class Resources(dict):
# 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 @@ class ReservedResources(log.Origin):
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: