Hi folks,
here is an example of STAF's logging capabilities - e.g. what it logs
and how does the output look like.
The nice features of STAF logging are:
* delegated logging - all logging on one machine is forwarded to
another machine - e.g. test coordinator
* marshalling/unmarshalling of structured data - see below.
* introspection/querying - STAF can be used not only to log data, but
to query what logs are present, producing log summaries etc.
For test writers the first part may be of interest, as the plan is to
write a rhts2STAF adaptor for legacy rhts tests, so beakerlib and STAF
can be used within one test without problems.
For beaker developers, it's the Python code and results which are of
interest, as the planned STAF2Beaker adaptor will use such a code to
collect logs from test machine and feed them to Scheduler's results DB.
See the end of the attached file.
BTW, the same would work with Perl or Ruby, as STAF provides bindings
for these languages, and few more :-)
Cheers,
Marian
# -- FMT:Command line input with output inilined
# Do not get scared by all the UPPERCASE (it is not necessary, STAF is case insensitive,) it is used here only to distinguish STAF keywords.
# Set STAF_QUIET_MODE to limit junk lines printed by STAF:
$ export STAF_QUIET_MODE=1
# Script run manually - allocate handle to be used throughout the script:
$ export STAF_STATIC_HANDLE=$(STAF local HANDLE CREATE HANDLE NAME "query-example.sh")
# Handle 913 allocated.
# Fill in logs with some messages:
$ STAF local LOG LOG GLOBAL LEVEL info LOGNAME temp MESSAGE info to global:temp
$ STAF local LOG LOG MACHINE LEVEL warning LOGNAME temp MESSAGE warning to machine:temp
$ STAF local LOG LOG HANDLE LEVEL error LOGNAME temp MESSAGE error to handle:temp
$ STAF local LOG LOG MACHINE LEVEL pass LOGNAME temp MESSAGE pass to machine:temp
$ STAF local LOG LOG GLOBAL LEVEL fail LOGNAME temp MESSAGE fail to global:temp
# Query what log files are present:
$ STAF local LOG LIST GLOBAL
Log Name Date-Time U-Size L-Size
-------- ----------------- ------ ------
temp 20090615-21:36:08 0 220
MyLog 20090611-01:18:11 0 824
$ STAF local LOG LIST MACHINES
beaker-lm1
$ STAF local LOG LIST MACHINE {STAF/Config/Machine}
Log Name Date-Time U-Size L-Size
-------- ----------------- ------ ------
temp 20090615-21:36:08 0 225
MyLog 20090529-15:46:15 0 103
$ STAF local LOG LIST MACHINE {STAF/Config/Machine} HANDLE 913
Log Name Date-Time U-Size L-Size
-------- ----------------- ------ ------
temp 20090615-21:36:07 0 111
# Query the logs just produced:
# ... GLOBAL
$ STAF local LOG QUERY GLOBAL LOGNAME temp
Date-Time Level Message
----------------- ----- -------------------
20090615-21:36:07 Info info to global:temp
20090615-21:36:08 Fail fail to global:temp
$ STAF local LOG QUERY GLOBAL LOGNAME temp LONG
R# Date-Time Machine H# Name User Endpoint Level Message
-- --------- ---------- --- -------- -------- ------------- ----- -------------
1 20090615- beaker-lm1 913 query-ex none://a local://local Info info to globa
21:36:07 ample.sh nonymous l:temp
2 20090615- beaker-lm1 913 query-ex none://a local://local Fail fail to globa
21:36:08 ample.sh nonymous l:temp
$ STAF local LOG QUERY GLOBAL LOGNAME temp STATS
Fatal : 0
Error : 0
Warning: 0
Info : 1
Trace : 0
Trace2 : 0
Trace3 : 0
Debug : 0
Debug2 : 0
Debug3 : 0
Start : 0
Stop : 0
Pass : 0
Fail : 1
Status : 0
User1 : 0
User2 : 0
User3 : 0
User4 : 0
User5 : 0
User6 : 0
User7 : 0
User8 : 0
# ... MACHINE and MACHINE/HANDLE:
$ STAF local LOG QUERY MACHINE {STAF/Config/Machine} LOGNAME temp LONG
R# Date-Time Machine H# Name User Endpoint Level Message
-- --------- ---------- --- -------- -------- ------------- ----- -------------
1 20090615- beaker-lm1 913 query-ex none://a local://local Warni warning to ma
21:36:07 ample.sh nonymous ng chine:temp
2 20090615- beaker-lm1 913 query-ex none://a local://local Pass pass to machi
21:36:08 ample.sh nonymous ne:temp
$ STAF local LOG QUERY MACHINE {STAF/Config/Machine} HANDLE 913 LOGNAME temp LONG
R# Date-Time Machine H# Name User Endpoint Level Message
-- --------- ---------- --- -------- -------- ------------- ----- -------------
1 20090615- beaker-lm1 913 query-ex none://a local://local Error error to hand
21:36:07 ample.sh nonymous le:temp
# The output might be fine for humans, but we would like something more machine-friendly:
$ export STAF_PRINT_MODE=Verbose
$ STAF local LOG LIST GLOBAL
[
{
Log Name : temp
Date-Time: 20090615-21:36:08
U-Size : 0
L-Size : 220
}
{
Log Name : MyLog
Date-Time: 20090611-01:18:11
U-Size : 0
L-Size : 824
}
]$ STAF local LOG QUERY GLOBAL LOGNAME temp
[
{
Date-Time: 20090615-21:36:07
Level : Info
Message : info to global:temp
}
{
Date-Time: 20090615-21:36:08
Level : Fail
Message : fail to global:temp
}
]
# It is much better, but still not the best one can get from STAF.
# Let's see what PySTAF has to offer:
# Following python file:
$ cat /tmp/tmp.KRgcJnmmSq
from PySTAF import *
import sys
try:
handle = STAFHandle("MyTest")
except STAFException, e:
print "ERROR: Error registering with STAF, RC: %d" % e.rc
sys.exit(e.rc)
def submit(*args):
print "calling handle.submit(*%s)" % repr(args)
result = handle.submit(*args)
if result.rc != STAFResult.Ok:
print 'ERROR: ... failed with RC=%s Result=%s' % (repr(result.rc), repr(result.result))
sys.exit(result.rc)
return result
print "# Query existing logs:"
result = submit('local', 'LOG', 'LIST GLOBAL')
print '... Returned repr(result.resultObj)): %s' % repr(result.resultObj)
print '... or, "pretty-printed", repr(result.resultContext)): %s' % repr(result.resultContext)
result = submit('local', 'LOG', 'QUERY GLOBAL LOGNAME temp')
print '... Returned repr(result.resultObj)): %s' % repr(result.resultObj)
print '... or, "pretty-printed", repr(result.resultContext)): %s' % repr(result.resultContext)
print "\n# Marshalling strucutred data:"
testObj = { 'data_type':'testInfo', 'test':'/examples/STAF/query-example', 'subtest':'/python', 'test_type':'temp', 'outputs':['/tmp/staf-query-example.out', '/var/log/messages'] }
print "marshall(%s)" % repr(testObj)
print "... will produce: %s" % repr(marshall(testObj))
print "\n# and storing and retrieving such a strucutred data (using STAF LOG service):"
result = submit('local', 'LOG', 'LOG GLOBAL LEVEL info LOGNAME py_temp MESSAGE %s' % marshall(testObj))
result = submit('local', 'LOG', 'QUERY GLOBAL LOGNAME py_temp')
print '... Retrieved following "raw" data from log: repr(result.result):\n%s' % repr(result.result)
mc = unmarshall(result.result)
print '... or "pretty-printed" as repr(unmarshall(result.result)) [ or simpler repr(result.resultContext) ]:\n%s' % mc
print '... or more Pythonic as repr(unmarshall(result.result).getRootObject()) [ or simpler repr(result.resultObj) ]:\n%s' % mc.getRootObject()
result = submit('local', 'LOG', 'QUERY GLOBAL LOGNAME py_temp LONG')
print '... produced:\n%s' % repr(result.resultObj)
print "\n# Python clean-up:"
result = submit('local', 'LOG', 'DELETE GLOBAL LOGNAME py_temp CONFIRM')
# will produce nice formatted output:
$ python /tmp/tmp.KRgcJnmmSq
/usr/local/staf/lib/PySTAF.py:9: RuntimeWarning: Python C API version mismatch for module PYSTAF: This Python has API version 1013, module PYSTAF has version 1011.
import PYSTAF
# Query existing logs:
calling handle.submit(*('local', 'LOG', 'LIST GLOBAL'))
... Returned repr(result.resultObj)): [{'staf-map-class-name': 'STAF/Service/Log/ListLogs', 'size': '220', 'logName': 'temp', 'upperSize': '0', 'timestamp': '20090615-21:36:08'}, {'staf-map-class-name': 'STAF/Service/Log/ListLogs', 'size': '824', 'logName': 'MyLog', 'upperSize': '0', 'timestamp': '20090611-01:18:11'}]
... or, "pretty-printed", repr(result.resultContext)): [
{
Log Name : temp
Date-Time: 20090615-21:36:08
U-Size : 0
L-Size : 220
}
{
Log Name : MyLog
Date-Time: 20090611-01:18:11
U-Size : 0
L-Size : 824
}
]
calling handle.submit(*('local', 'LOG', 'QUERY GLOBAL LOGNAME temp'))
... Returned repr(result.resultObj)): [{'staf-map-class-name': 'STAF/Service/Log/LogRecord', 'message': 'info to global:temp', 'level': 'Info', 'timestamp': '20090615-21:36:07'}, {'staf-map-class-name': 'STAF/Service/Log/LogRecord', 'message': 'fail to global:temp', 'level': 'Fail', 'timestamp': '20090615-21:36:08'}]
... or, "pretty-printed", repr(result.resultContext)): [
{
Date-Time: 20090615-21:36:07
Level : Info
Message : info to global:temp
}
{
Date-Time: 20090615-21:36:08
Level : Fail
Message : fail to global:temp
}
]
# Marshalling strucutred data:
marshall({'test': '/examples/STAF/query-example', 'subtest': '/python', 'test_type': 'temp', 'data_type': 'testInfo', 'outputs': ['/tmp/staf-query-example.out', '/var/log/messages']})
... will produce: '@SDT/{:216::4:test@SDT/$S:28:/examples/STAF/query-example:7:subtest@SDT/$S:7:/python:9:test_type@SDT/$S:4:temp:9:data_type@SDT/$S:8:testInfo:7:outputs@SDT/[2:66:@SDT/$S:27:/tmp/staf-query-example.out@SDT/$S:17:/var/log/messages'
# and storing and retrieving such a strucutred data (using STAF LOG service):
calling handle.submit(*('local', 'LOG', 'LOG GLOBAL LEVEL info LOGNAME py_temp MESSAGE @SDT/{:216::4:test@SDT/$S:28:/examples/STAF/query-example:7:subtest@SDT/$S:7:/python:9:test_type@SDT/$S:4:temp:9:data_type@SDT/$S:8:testInfo:7:outputs@SDT/[2:66:@SDT/$S:27:/tmp/staf-query-example.out@SDT/$S:17:/var/log/messages'))
calling handle.submit(*('local', 'LOG', 'QUERY GLOBAL LOGNAME py_temp'))
... Retrieved following "raw" data from log: repr(result.result):
'@SDT/*:675:@SDT/{:330::13:map-class-map@SDT/{:302::26:STAF/Service/Log/LogRecord@SDT/{:261::4:keys@SDT/[3:198:@SDT/{:60::12:display-name@SDT/$S:9:Date-Time:3:key@SDT/$S:9:timestamp@SDT/{:52::12:display-name@SDT/$S:5:Level:3:key@SDT/$S:5:level@SDT/{:56::12:display-name@SDT/$S:7:Message:3:key@SDT/$S:7:message:4:name@SDT/$S:26:STAF/Service/Log/LogRecord@SDT/[1:322:@SDT/%:311::26:STAF/Service/Log/LogRecord@SDT/$S:17:20090615-21:36:08@SDT/$S:4:Info@SDT/$S:227:@SDT/{:216::4:test@SDT/$S:28:/examples/STAF/query-example:7:subtest@SDT/$S:7:/python:9:test_type@SDT/$S:4:temp:9:data_type@SDT/$S:8:testInfo:7:outputs@SDT/[2:66:@SDT/$S:27:/tmp/staf-query-example.out@SDT/$S:17:/var/log/messages'
... or "pretty-printed" as repr(unmarshall(result.result)) [ or simpler repr(result.resultContext) ]:
[
{
Date-Time: 20090615-21:36:08
Level : Info
Message : {
test : /examples/STAF/query-example
subtest : /python
test_type: temp
data_type: testInfo
outputs : [
/tmp/staf-query-example.out
/var/log/messages
]
}
}
]
... or more Pythonic as repr(unmarshall(result.result).getRootObject()) [ or simpler repr(result.resultObj) ]:
[{'staf-map-class-name': 'STAF/Service/Log/LogRecord', 'message': {'test': '/examples/STAF/query-example', 'subtest': '/python', 'test_type': 'temp', 'data_type': 'testInfo', 'outputs': ['/tmp/staf-query-example.out', '/var/log/messages']}, 'level': 'Info', 'timestamp': '20090615-21:36:08'}]
calling handle.submit(*('local', 'LOG', 'QUERY GLOBAL LOGNAME py_temp LONG'))
... produced:
[{'staf-map-class-name': 'STAF/Service/Log/LogRecordLong', 'endpoint': 'local://local', 'handle': '914', 'level': 'Info', 'timestamp': '20090615-21:36:08', 'machine': 'beaker-lm1', 'user': 'none://anonymous', 'message': {'test': '/examples/STAF/query-example', 'subtest': '/python', 'test_type': 'temp', 'data_type': 'testInfo', 'outputs': ['/tmp/staf-query-example.out', '/var/log/messages']}, 'recordNumber': '1', 'handleName': 'MyTest'}]
# Python clean-up:
calling handle.submit(*('local', 'LOG', 'DELETE GLOBAL LOGNAME py_temp CONFIRM'))
# SH clean up:
$ STAF local LOG DELETE GLOBAL LOGNAME temp CONFIRM
$ STAF local LOG DELETE MACHINE {STAF/Config/Machine} LOGNAME temp CONFIRM
$ STAF local LOG DELETE MACHINE {STAF/Config/Machine} HANDLE 913 LOGNAME temp CONFIRM
$ STAF local HANDLE DELETE HANDLE 913