python app logging

[bw447]

I'm trying to setup a python app just so that I can test out the logging function. This switch that I'm running this on is an x460 running EXOS 16.1.3.6 Below is the script that I was testing. I just wan to make one little entry to the trace buffer, however after running it I'm not seeing the entry in the buffer. That's one question, the other is that if I just want to create a log message that can be seen with the 'show log' command do I use the api.exec_cli(['create log message ......']) method? Thanks in advance! import logging from exos import api logger = logging.getLogger("myapp") logger.setLevel(logging.DEBUG) logHandler = api.TraceBufferHandler("mybuf", 20480) logHandler.setLevel(logging.DEBUG) logger.addHandler(logHandler) if __name__ == '__main__': try: logger.debug("Here is a long entry that cannot be seen") except BaseException, e: logger.debug("Exception on startup, {}".format(e), exc_info=True) Below are the commands I ran on the switch to setup the process. * Test-Switch.41 # create process TestPython python-module Proc.py start on-demand creating TestPython... * Test-Switch.42 # clear log * Test-Switch.43 # start process "TestPython" Started TestPython successfully * Test-Switch.44 # debug ems show trace TestPython all 10/12/2016 11:38:03.114425 [1] Created service group 1 10/12/2016 11:38:03.116105 [2] Added service 0x419ff0 to group 1 10/12/2016 11:38:03.116298 [3] Added service 0x419ee0 to group 1 10/12/2016 11:38:03.117059 [4] Added service 0x41b550 to group 1 10/12/2016 11:38:03.117576 [5] ipmlTcpConnect: Successful local connect to port 7655 for peer 2 fd 7 10/12/2016 11:38:03.117898 [6] ipmlVerifyConnection: Successfully verified connection for peer 2 to 10.0.1.2:7655/PID:0 10/12/2016 11:38:03.120554 [8] main Booting... 10/12/2016 11:38:04.241007 [9] main Initialized... 10/12/2016 11:38:04.241429 [10] main Starting dispatcher 10/12/2016 11:38:04.241861 [11] dispatchClientConnectCallback(-121) dsRequestRxData peer 2 10/12/2016 11:38:04.242643 [12] ipmlTcpConnect: Successful local connect to port 7656 for peer 3 fd 8 10/12/2016 11:38:04.242892 [13] ipmlVerifyConnection: Successfully verified connection for peer 3 to 10.0.1.2:7656/PID:0 10/12/2016 11:38:04.247174 [14] dispatchClientConnectCallback(-121) epmClientRecv peer 3 10/12/2016 11:38:04.248317 [15] Added service 0x499998 to group 1 10/12/2016 11:38:04.248642 [16] ipmlTcpConnect: Successful local connect to port 7658 for peer 4 fd 11 10/12/2016 11:38:04.248914 [17] ipmlVerifyConnection: Successfully verified connection for peer 4 to 10.0.1.2:7658/PID:0 10/12/2016 11:38:04.249279 [18] Added service 0x41ba20 to group 1 10/12/2016 11:38:04.249560 [19] ipmlTcpConnect: Successful local connect to port 7657 for peer 5 fd 66 10/12/2016 11:38:04.249845 [20] ipmlVerifyConnection: Successfully verified connection for peer 5 to 10.0.1.2:7657/PID:0 10/12/2016 11:38:04.254863 [21] dispatchClientConnectCallback(-121) emsClient peer 5 10/12/2016 11:38:04.269421 [22] dispatchClientConnectCallback(-121) dmDispatcherCallBack peer 4 10/12/2016 11:38:04.361345 [99] Added Object: techSupport, ID 50000022, Index 34, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.361928 [100] dmSend: 0027 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000022, 0, (nil) 10/12/2016 11:38:04.362102 [101] Added Object: acl, ID 50000023, Index 35, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.362680 [102] dmSend: 0028 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000023, 0, (nil) 10/12/2016 11:38:04.362868 [103] Added Object: netTools, ID 50000024, Index 36, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.363450 [104] dmSend: 0029 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000024, 0, (nil) 10/12/2016 11:38:04.363620 [105] Added Object: telnetd, ID 50000025, Index 37, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.364176 [106] dmSend: 002A Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000025, 0, (nil) 10/12/2016 11:38:04.364345 [107] Added Object: rip, ID 50000026, Index 38, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.364969 [108] dmSend: 002B Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000026, 0, (nil) 10/12/2016 11:38:04.365142 [109] Added Object: ipfix, ID 50000027, Index 39, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.366003 [110] dmSend: 002C Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000027, 0, (nil) 10/12/2016 11:38:04.366618 [111] Added Object: dosprotect, ID 50000028, Index 40, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.366850 [112] dmSend: 002D Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000028, 0, (nil) 10/12/2016 11:38:04.367390 [113] Added Object: thttpd, ID 50000029, Index 41, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.367612 [114] dmSend: 002E Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000029, 0, (nil) 10/12/2016 11:38:04.368155 [115] Added Object: poe, ID 5000002A, Index 42, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.368383 [116] dmSend: 002F Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000002A, 0, (nil) 10/12/2016 11:38:04.368542 [117] Added Object: xmlc, ID 5000002B, Index 43, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.369104 [118] dmSend: 0030 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000002B, 0, (nil) 10/12/2016 11:38:04.369311 [119] Added Object: etmon, ID 5000002C, Index 44, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.369884 [120] dmSend: 0031 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000002C, 0, (nil) 10/12/2016 11:38:04.370142 [121] Added Object: ipSecurity, ID 5000002D, Index 45, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.371289 [122] dmSend: 0032 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000002D, 0, (nil) 10/12/2016 11:38:04.371581 [123] Added Object: upm, ID 5000002E, Index 46, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.372262 [124] dmSend: 0033 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000002E, 0, (nil) 10/12/2016 11:38:04.372436 [125] Added Object: hclag, ID 5000002F, Index 47, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.373046 [126] dmSend: 0034 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000002F, 0, (nil) 10/12/2016 11:38:04.373223 [127] Added Object: dot1ag, ID 50000030, Index 48, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.374068 [128] dmSend: 0035 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000030, 0, (nil) 10/12/2016 11:38:04.374273 [129] Added Object: vmt, ID 50000031, Index 49, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.375022 [130] dmSend: 0036 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000031, 0, (nil) 10/12/2016 11:38:04.375202 [131] Added Object: vsm, ID 50000032, Index 50, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.375787 [132] dmSend: 0037 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000032, 0, (nil) 10/12/2016 11:38:04.375956 [133] Added Object: erps, ID 50000033, Index 51, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.376517 [134] dmSend: 0038 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000033, 0, (nil) 10/12/2016 11:38:04.376690 [135] Added Object: fcoe, ID 50000034, Index 52, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.377283 [136] dmSend: 0039 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000034, 0, (nil) 10/12/2016 11:38:04.377454 [137] Added Object: mrp, ID 50000035, Index 53, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.378025 [138] dmSend: 003A Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000035, 0, (nil) 10/12/2016 11:38:04.378198 [139] Added Object: ntp, ID 50000036, Index 54, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.378767 [140] dmSend: 003B Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000036, 0, (nil) 10/12/2016 11:38:04.378951 [141] Added Object: twamp, ID 50000037, Index 55, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.379557 [142] dmSend: 003C Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000037, 0, (nil) 10/12/2016 11:38:04.379736 [143] Added Object: policy, ID 50000038, Index 56, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.380653 [144] dmSend: 003D Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000038, 0, (nil) 10/12/2016 11:38:04.381186 [145] Added Object: idMgr, ID 50000039, Index 57, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.381420 [146] dmSend: 003E Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000039, 0, (nil) 10/12/2016 11:38:04.382103 [147] Added Object: epm, ID 5000003A, Index 58, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.382332 [148] dmSend: 003F Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000003A, 0, (nil) 10/12/2016 11:38:04.382885 [149] Added Object: xmld, ID 5000003B, Index 59, State READY, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.383133 [150] dmSend: 0040 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 5000003C, 0, (nil) 10/12/2016 11:38:04.383694 [151] Added Object: BlakeProcess, ID 5000003C, Index 60, State DELETED, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.383919 [152] dmSend: 0041 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000040, 0, (nil) 10/12/2016 11:38:04.384119 [153] Added Object: BlakeProc2, ID 5000003D, Index 61, State DELETED, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.384716 [154] dmSend: 0042 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000042, 0, (nil) 10/12/2016 11:38:04.385261 [155] Added Object: BlakeProc3, ID 5000003E, Index 62, State DELETED, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.385479 [156] dmSend: 0043 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000044, 0, (nil) 10/12/2016 11:38:04.386037 [157] Added Object: BlakeProc4, ID 5000003F, Index 63, State DELETED, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.386263 [158] dmSend: 0044 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000046, 0, (nil) 10/12/2016 11:38:04.386810 [159] Added Object: BlakeProc5, ID 50000040, Index 64, State DELETED, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.387037 [160] dmSend: 0045 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000048, 0, (nil) 10/12/2016 11:38:04.387226 [161] Added Object: BP, ID 50000041, Index 65, State DELETED, Flags 0000, (nil), LEN 104 10/12/2016 11:38:04.387833 [162] dmSend: 0046 Peer 4, DM_MSG_GETNEXT_OBJ_INFO, Obj 50000049, 0, (nil) 10/12/2016 11:38:04.388457 [163] dmSend: 0047 Peer 4, DM_MSG_PROCESS_STATE, Obj 50000000, 104, 0x41b88c 10/12/2016 11:38:04.388591 [164] dmEvent: 0047 Peer 4, DM_MSG_DMINSYNC, Obj 0000, 1, (nil) 10/12/2016 11:38:04.393769 [165] expyCoreLibraryEventHandler Core libraries ready... 10/12/2016 11:38:04.394033 [166] TestPython: Checkpoint Dependecy = 1 0 0 10/12/2016 11:38:04.394911 [167] StartTIMER work=0x4a5428 fn=0x2aec9508 c1=0x2aecb82c c2=(nil) sec=1.0) 10/12/2016 11:38:04.395046 [168] dmEvent: 0047 Peer 4, DM_MSG_BE_PRIMARY, Obj 0000, 0, (nil) 10/12/2016 11:38:04.395117 [169] StartTIMER work=0x4a54b0 fn=0x2aecba34 c1=(nil) c2=(nil) sec=0.0) 10/12/2016 11:38:04.395176 [170] TestPython: ft_server_start (nil) (nil) 10/12/2016 11:38:04.395414 [171] TestPython: Registered service TestPython-P 10/12/2016 11:38:04.395537 [172] TestPython: TestPython Process State is BOOTING 10C0 10/12/2016 11:38:04.395572 [173] dmEvent: 0DEC Peer 4, DM_MSG_PROCESS_STATE, Obj 50000000, 104, 0x49fbc8 10/12/2016 11:38:04.397938 [174] TestPython-P: registered with port:7771 10/12/2016 11:38:04.398058 [175] ipmlTcpInit: socket 67 is created for port 7771 10/12/2016 11:38:04.399828 [176] Added service 0x4a76b8 to group 1 10/12/2016 11:38:04.415572 [177] Added service 0x4a7458 to group 1 10/12/2016 11:38:04.415868 [178] ipmlTcpConnect: Successful local connect to port 7687 for peer 6 fd 70 10/12/2016 11:38:04.416136 [179] ipmlVerifyConnection: Successfully verified connection for peer 6 to 10.0.1.2:7687/PID:0 10/12/2016 11:38:04.420425 [180] dispatchClientConnectCallback(-121) cmDispatcherCallback peer 6 10/12/2016 11:38:04.421720 [181] expyConfigLibraryEventHandler Config lib ready. 10/12/2016 11:38:04.421769 [182] TestPython: Process State for TestPython is LOADCFG 10/12/2016 11:38:04.423177 [183] cfg_instance TestPython 0 --> 1 10/12/2016 11:38:04.423196 [184] TestPython to LOAD_CFG now 10/12/2016 11:38:04.423236 [185] dmEvent: 0DEC Peer 4, DM_MSG_LOAD_CFG, Obj 0000, 0, (nil) 10/12/2016 11:38:04.423361 [186] StartTIMER work=0x4a7568 fn=0x2aecb914 c1=(nil) c2=(nil) sec=0.100000) 10/12/2016 11:38:04.423428 [187] dmSend: 0048 Peer 4, DM_MSG_PROCESS_STATE, Obj 50000000, 104, 0x41b88c 10/12/2016 11:38:04.423541 [188] TestPython: Process State for TestPython is READY 10/12/2016 11:38:04.427050 [189] dmSend: 0049 Peer 4, DM_MSG_PROCESS_STATE, Obj 50000000, 104, 0x41b88c 10/12/2016 11:38:04.427340 [190] expyStart Starting... 10/12/2016 11:38:04.449706 [191] pyext_aaa.c.536:: Loading _exos_ext_aaa... 10/12/2016 11:38:04.456895 [192] pyext_cm_frontend.c.404:: Loading _exos_ext_cm_frontend... 10/12/2016 11:38:04.458767 [193] pyext_lm.c.257:: Loading _exos_ext_lm... 10/12/2016 11:38:04.603792 [194] expyStart Started. 10/12/2016 11:38:04.604263 [195] TestPython: request_standby_config Skipped 10/12/2016 11:38:04.604655 [196] TestPython: TestPython Process State is LOADCFG 18E1 10/12/2016 11:38:04.604726 [197] dmEvent: 0DED Peer 4, DM_MSG_PROCESS_STATE, Obj 50000000, 104, 0x49fbc8 10/12/2016 11:38:04.604972 [198] TestPython: TestPython Process State is READY 18D1 10/12/2016 11:38:04.605006 [199] dmEvent: 0DEE Peer 4, DM_MSG_PROCESS_STATE, Obj 50000000, 104, 0x49fbc8 10/12/2016 11:38:05.053620 [200] Begin trace buffer 10/12/2016 11:38:05.060059 [201] Begin trace buffer 10/12/2016 11:38:05.402832 [202] dmSend: 004A Peer 4, DM_MSG_OBJ_INFO, Obj 50000000, 104, 0x41b88c * Test-Switch.45 # debug ems show trace TestPython all | include entry

[Dave_Hammers]

I like to use a formatter to get a little more display control:
import logging
from exos import api

logHandler = api.TraceBufferHandler("mybuf", 20480)
logHandler.setFormatter(logging.Formatter(
'%(levelname)s:%(threadName)s:%(name)s:%(funcName)s.%(lineno)s:: '
'%(message)s'))
logHandler.setLevel(logging.DEBUG)
logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)
logger.addHandler(logHandler)

if __name__ == '__main__':
try:
logger.debug("Here is a long entry that cannot be seen")
except BaseException, e:
logger.debug("Exception on startup, {}".format(e), exc_info=True)

10/12/2016 18:03:33.330487 [183] pyext_epm.c.48:: EPM message 24880
10/12/2016 18:03:33.330512 [184] pyext_epm.c.48:: EPM message 536941329
10/12/2016 18:03:33.379564 [185] TestPython: request_standby_config Skipped
10/12/2016 18:03:33.494495 [186] Begin trace buffer
10/12/2016 18:03:33.494901 [187] Begin trace buffer
10/12/2016 18:03:33.495707 [188] DEBUG:ExpyRunner:myapp:.16:: Here is a long entry that cannot be seen
10/12/2016 18:03:34.279345 [189] dmSend: 0044 Peer 4, DM_MSG_OBJ_INFO, Obj 50000000, 104, 0x41b88c

[bw447]

Thanks for the info Dave. I removed the file extension from the command when I created the process and it worked. I've updated my base code to include your extra logger formatter for a better display. Thanks!

[Stephane_Grosj1]

Hi,

What about not including the ".py" in the create process command.
Then doing:
debug ems show trace "TestPython" mybuf

On a 21.1 VM, I copy/paste your code in testpython.py

* sw3.3 # create process TestPython python-module testpython start on-demand
creating TestPython...
* sw3.4 # clear log
* sw3.5 # start process TestPython
Started TestPython successfully
* sw3.6 #
* sw3.6 # debug ems show trace "TestPython" mybuf
10/12/2016 17:25:50.582828 [202] Begin trace buffer
10/12/2016 17:25:50.582908 [203] Here is a long entry that cannot be seen
* sw3.7 #

[bw447]

Stephane...you are a wizard!  I removed the .py and it worked like a charm! Thanks!