log file for device server only includes device log messages

[carandraug]

Each device has its own logger instance, and the device server adds a RotatingFileHandler to each of them. Because the handler is added to the device logger, messages from other loggers are not logged in the file.

For example, log records from Pyro or pySerial would probably make sense to be included.

[carandraug]

This issue is not limited to log messages from other packages. Because we have one log per device, then microscope log messages that don't happen in that device do not appear. We need to pass the device logger to any other class.

For example, if we wanted the Setting class to emit log messages, then the device would have to pass the logger to each Setting instance. Similarly, I have a connection class that wraps the interface to a controller. The controller device has an instance of this connection class. To get messages logged, the device logger needs to be passed to the connection instance. The more one uses composition, the more passing around a logger will be needed.

In the case of a controller device, a device has multiple children devices each with their own logger. Only after initialization of the controller device do we know what children devices will be created and what loggers will exist. However, by then, the children devices will already have been created. So even if the device server adds handlers to those children device loggers, we are missing the log messages from the device initialization.

[mickp]

The motivation for this was so that each process would write logs to a separate file, thereby avoiding clashes, and the files would have filenames that gave some idea of their source. Logging from within contained classes would be very useful, though. I think this should be achievable by ditching the _logger class member, and using logging.getLogger() - if no loggers are specifically created, I think this should return the same logger for any call within a given process. We need to set handlers on the root logger for each process, so maybe we need to wrap getLogger() to check for / apply handlers.

On Tue, 8 Oct 2019 at 16:40, Carnë Draug notifications@github.com wrote:

This issue is not limited to log messages from other packages. Because we have one log per device, then microscope log messages that don't happen in that device do not appear. We need to pass the device logger to any other class.

For example, if we wanted the Setting class to emit log messages, then the device would have to pass the logger to each Setting instance. Similarly, I have a connection class that wraps the interface to a controller. The controller device has an instance of this connection class. To get messages logged, the device logger needs to be passed to the connection instance. The more one uses composition, the more passing around a logger will be needed.

In the case of a controller device, a device has multiple children devices each with their own logger. Only after initialization of the controller device do we know what children devices will be created and what loggers will exist. However, by then, the children devices will already have been created. So even if the device server adds handlers to those children device loggers, we are missing the log messages from the device initialization.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/MicronOxford/microscope/issues/110?email_source=notifications&email_token=ABHGTL272CUMOKVGVMHRH3DQNSSWDA5CNFSM4I6ILAR2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEAUT57A#issuecomment-539574012, or mute the thread https://github.com/notifications/unsubscribe-auth/ABHGTL7Y2A5W343UAH2OMCDQNSSWDANCNFSM4I6ILARQ .

--

---

Mick Phillips

---

[carandraug]

I spoke more with Mick about this. Instead of using the root logger we should use logging.getLogger("microscope"), we can keep the current log filename code, and just change the adding of the log handlers to the root logger.

Currently, Python logging best practices is to use logging.getLogger(__name__) on each module but because of our many modules, I don't think this is very useful. We can also use logging.getLogger("microscope.devices") for all device related logging and leave "microscope.x" for future parts of the package. However, for now this seems overkill.

If a user wants to use the loggers, we are less likely to break existing code if we later split a the microscope logger into multiple children than if we do the other way around (use of dots on the logger name creates children and parent loggers and log records go down the chain).

[carandraug]

I have a suggested fix on my "logging-issue-110" branch. Can someone try it out? It basically rests on the assumption that each device server runs on its own process. Each process means that each has its own independent root logger and so we can just configure that to handle all records.

The whole thing of one root logger per process is in theory but the way each process gets a root logger is dependent on multiprocessing start method whose default and behaviour is platform dependent. Can someone else give it a try?

[mickp]

Seems to work under MSWIN. Device initialization line and the Pyro URI now show up in the individual device logs, arising form module __mp_main__.

[iandobbie]

Seems to be the same on macos. Any particular test other than starting devices and seeing the logs appear or get appended to?

[carandraug]

Seems to be the same on macos. Any particular test other than starting devices and seeing the logs appear or get appended to?

The important thing is making sure that the devices go to the right file. Namely, logs from the main process ending on the device files or vice-versa.

[carandraug]

Rebased and merged. Closing as fixed.