Let's observe the Python Logging cookbook SocketHandler
Purpose
In implementing logging using SocketHandlerL, I proceeded while observing packets with WireShark to understand the sample code of "Sending and receiving logging events over the network" described in the Logging cookbook of the Python document.
reference
See the link below in the Python documentation. Sending and receiving logging events over the network (https://docs.python.org/ja/3.7/howto/logging-cookbook.html#sending-and-receiving-logging-events-across-a-network)
Sample code
Sender
The sample code on the sender side is as it is described in the Python document Logging cookbook.
Sample code
import logging, logging.handlers
rootLogger = logging.getLogger('')
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# don't bother with a formatter, since a socket handler sends the event as
# an unformatted pickle
rootLogger.addHandler(socketHandler)
# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')
# Now, define a couple of other loggers which might represent areas in your
# application:
logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')
logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')
Receiver
The sample code on the receiving side is the code described in the Python document Logging cookbook with some comments and print statements.
Sample code
import pickle
import logging
import logging.handlers
import socketserver
import struct
import json
class LogRecordStreamHandler(socketserver.StreamRequestHandler):
"""Handler for a streaming logging request.
This basically logs the record using whatever logging policy is
configured locally.
"""
def handle(self):
"""
Handle multiple requests - each expected to be a 4-byte length,
followed by the LogRecord in pickle format. Logs the record
according to whatever policy is configured locally.
"""
while True:
#Waiting for reception...When received, read 4 bytes and get the length of the data part
chunk = self.connection.recv(4)
#Display the first 4 bytes in hexadecimal
print(chunk.hex())
if len(chunk) < 4:
break
#Convert received length to decimal, paying attention to endianness
slen = struct.unpack('>L', chunk)[0]
print(slen)
#Get the acquired reception length
chunk = self.connection.recv(slen)
#Let's display it in hexadecimal.
#Now compare it with the data captured by WireShark.
print(chunk.hex())
#Here, if the retrieved data is less than the reception length, it loops until it can be received.
while len(chunk) < slen:
chunk = chunk + self.connection.recv(slen - len(chunk))
print(chunk.hex())
#Since it will be pickled, expand it
obj = self.unPickle(chunk)
#Expanded to dict. In the documentation it is referred to as attrdict.
print(type(obj),json.dumps(obj,indent=4))
#Create a new LogRecord instance from attrdict
# https://docs.python.org/ja/3/library/logging.html?highlight=makelogrecord#logging.makeLogRecord
record = logging.makeLogRecord(obj)
self.handleLogRecord(record)
def unPickle(self, data):
return pickle.loads(data)
def handleLogRecord(self, record):
# if a name is specified, we use the named logger rather than the one
# implied by the record.
if self.server.logname is not None:
name = self.server.logname
else:
name = record.name
logger = logging.getLogger(name)
# N.B. EVERY record gets logged. This is because Logger.handle
# is normally called AFTER logger-level filtering. If you want
# to do filtering, do it at the client end to save wasting
# cycles and network bandwidth!
# https://docs.python.org/ja/3/library/logging.html#logging.Handler.handle
#Output log record according to the condition set on the sending side
logger.handle(record)
class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
"""
Simple TCP socket-based logging receiver suitable for testing.
"""
allow_reuse_address = True
def __init__(self, host='localhost',
port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
handler=LogRecordStreamHandler):
socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
self.abort = 0
self.timeout = 1
self.logname = None
def serve_until_stopped(self):
import select
abort = 0
while not abort:
rd, wr, ex = select.select([self.socket.fileno()],
[], [],
self.timeout)
if rd:
self.handle_request()
abort = self.abort
def main():
logging.basicConfig(
format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
tcpserver = LogRecordSocketReceiver()
print('About to start TCP server...')
tcpserver.serve_until_stopped()
if __name__ == '__main__':
main()
Execution result
WireShark capture
The sender is focusing on the part that received the first logging.info minutes. The part selected in blue is the data part.
The first thing you see is
About to start TCP server...
0000026a
618
In packet capture, the first 4 bytes of the data part is 0000026a, which is the same as the output. Converting this to a decimal number is 618. There is a notation of TCP Payload (622 bytes) in the packet capture, and it is exactly the same when the read 4 bytes are subtracted.
Next, the acquired data part is displayed. Obviously, it is the same as the captured data of the remaining data part.
7d71002858040000006e616d6571015804000000726f6f74710258030000006d7367710358260000004a61636b64617773206c6f7665206d792062696720737068696e78206f662071756172747a2e710458040000006172677371054e58090000006c6576656c6e616d6571065804000000494e464f710758070000006c6576656c6e6f71084b145808000000706174686e616d6571095870000000633a5c55736572735c46756e6168617368695c446f63756d656e74735c76735f636f64655f707974686f6e5c4e45582d534d4152545f53657474696e675f546f6f6c5f72656e65775c5f6578616d706c655f5c5f746573745f636f64655f5c546573745f536f636b65744c6f672e7079710a580800000066696c656e616d65710b5811000000546573745f536f636b65744c6f672e7079710c58060000006d6f64756c65710d580e000000546573745f536f636b65744c6f67710e58080000006578635f696e666f710f4e58080000006578635f7465787471104e580a000000737461636b5f696e666f71114e58060000006c696e656e6f71124b0c580800000066756e634e616d65711358080000003c6d6f64756c653e711458070000006372656174656471154741d7f81312eb188858050000006d7365637371164740850afa68000000580f00000072656c6174697665437265617465647117473fffe9ec00000000580600000074687265616471184d2c18580a0000007468726561644e616d657119580a0000004d61696e546872656164711a580b00000070726f636573734e616d65711b580b0000004d61696e50726f63657373711c580700000070726f63657373711d4dd424752e
Since this is pickled, it is expressed as dict format attrdict when expanded.
{
"name": "root",
"msg": "Jackdaws love my big sphinx of quartz.",
"args": null,
"levelname": "INFO",
"levelno": 20,
"pathname": "c:\\Users\\Funahashi\\Documents\\vs_code_python\\NEX-SMART_Setting_Tool_renew\\_example_\\_test_code_\\Test_SocketLog.py",
"filename": "Test_SocketLog.py",
"module": "Test_SocketLog",
"exc_info": null,
"exc_text": null,
"stack_info": null,
"lineno": 12,
"funcName": "<module>",
"created": 1608536546.772103,
"msecs": 772.1030712127686,
"relativeCreated": 4.986286163330078,
"thread": 12160,
"threadName": "MainThread",
"processName": "MainProcess",
"process": 14752
}
When I instantiated this dict with logging.makeLogRecord and passed it to logger.handle, I got the result of logging.
1 root INFO Jackdaws love my big sphinx of quartz.
Recommended Posts