Modify logging

[robcarver17]

• simplify any potential move to another database by ensuring everything is a dataframe
• reduce load on database
• I've literally never looked at the logs in the database it's just too painful
• will still have searchable fields in the text
• fairly sure it won't affect the ability to find eg status of methods etc as no other access

[bug-or-feature]

I'd like to propose a more radical solution. Maybe we could start a discussion?

[robcarver17]

Converted to discussion

[bug-or-feature]

I think we should abandon syslogdiag.logger.py and use Python's logging module instead.

Why?

• log statements should just include a message and a priority. There should be no logging logic in code
• what happens to the log message (console, file, database etc) should be defined in config at runtime, not code
• you may want to do different things with log messages in different contexts, eg prod, test, unit test, cloud, whatever
• if we use logging, then the logging system for PST will play nicely with the log output for dependencies
• logger.py is a bad design. Sorry. Good software should be loosely coupled with other components in its system. logger.py tightly couples everything in PST to everything else
• syslogdiag.logger.py is complex, hard to work with. logging is simple, flexible, powerful
• logging does everything that logger.py does. Better and faster
• I believe logging supports the context attributes that are so important to the logging in PST. There's two ways to do it, either with LoggerAdapters, or with Filters

[robcarver17]

Works for me.

Funnily enough I am pretty sure I used the python logger in my previous codebase (not open source). Can't remember why I didn't this time round. And I agree the logging code isn't great. It's probably the only bit of code I've never refactored.

To summarise what the logger needs to do:

• logs with attributes printed to enable easy search
• log eithier to screen (default for command line backtesting), a single text file, or to multiple text files based on attributes. I'm leaning towards the single file, as the echo files already provide a process by process view and a single log file would allow you to view what happened with a particular instrument over time. Looking at the logging cookbook, that might be tricky.
• Ideally one would be able to log to the same file from different processes.
• as with echos, text files should be archived daily through filename and then ultimately deleted (probably easier to use the existing code that does it for echos)
• include an email handler for log.critical

There is also some simplification to be done in the way individual log objects are created and labelled for run_... scripts, and because the log wouldn't need to be carted around with dataBlob the whole time.

Now I'm a bit rusty on this, but it's my understanding that once in the module I'd create a single instance of a logger with all the appropriate handling behaviour, and then import that into the various places I was using it? Then I'd add filters or adaptors and so on for context.

Or if logging to a single file was difficult, then maybe something closer to what I already do is better: set up a logger instance at the start of the run_... that logs to a specific file and then cart that round in dataBlob? Or is that sort of behaviour what we don't want, because it's tight coupling?

[tgibson11]

Now I'm a bit rusty on this, but it's my understanding that once in the module I'd create a single instance of a logger with all the appropriate handling behaviour, and then import that into the various places I was using it? Then I'd add filters or adaptors and so on for context.

This sounds right to me, but I don't have much experience with Python logging, so take my opinion with a grain of salt.

set up a logger instance at the start of the run_... that logs to a specific file and then cart that round in dataBlob? Or is that sort of behaviour what we don't want, because it's tight coupling?

That seems like exactly what we don't want. If you need to get a specific logger instance, there is logging.getLogger(name)

From Python docs:

All calls to this function with a given name return the same logger instance. This means that logger instances never need to be passed between different parts of an application.

[robcarver17]

OK that makes sense, but how do you set up the single log instance (adding the various handlers)? Presumably at a given entry point (normally run_... but not always) we'd need to set up the logger that can then be accessed. But what about the (numerous) use cases where we don't access through run_... I guess whenever a dataBlob is instanced it can check as part of it's job that a log handler has been instanced and stored with the appropriate handlers, and if not create one. That seems clunky, although arguably this is no different from what happens now.

Alternatively, and more complex, is to have a seperate logging process which also seems the simplest way (in the cookbook) to log to a single file from multiple processes eg using sockets. That will still need the stream handler set up, but the rest of the handling can be done by the logging process. That also seems overkill for backtesting, even if it makes sense for production.

[bug-or-feature]

To summarise what the logger needs to do

• include an email handler for log.critical

Do we also need to write emails to db as currently?

[robcarver17]

No I think emails should be written to a text file, as well as an attempt at being emailed

I think it's simpler if the logger doesn't need to know which database you are using

[bug-or-feature]

I should have said earlier - I'm happy to do this work. Although, because the logging code is everywhere, it might be quite hard to manage when there's lot of other refactoring going on.

One way to approach it: I could make a proof of concept, to check if the attribute stuff works OK. Or two, a sim and a prod one. And then we'd know how intrusive the changes would be.

I'm not concerned about the other requirements, single file, multiple files, console, email, archiving. That's all just config

[robcarver17]

And that's done. I did rename the logging method. I also renamed logger as pst_logger to avoid any confusion.

[robcarver17]

Andy, can you put a brief 'how to refactor some code with existing logging code in' post up please? I can see that pycharm is telling me I have some deprecated old logging code, but I could do with a few lines to explain what I do about it (okay change msg for debug is obvious but still).

[bug-or-feature]

Yep, I have some updates to the docs almost ready for a PR

[bug-or-feature]

I've submitted the PR (see #1190). There's a section in production.md about refactoring. But my plan is to refactor away all those deprecated methods myself in the next few days/weeks. Was just waiting for the dust to settle a little 😉

[robcarver17]

Great thank you.

[bug-or-feature]

This PR attempts to reduce some of the worst cases of excessive logging, messages that used to be suppressed by pst_logger._check_msg_logged_recently_or_update_hash().

Other cases were caused by the stack handler methods running continuously, with config like

  run_stack_handler:
    create_broker_orders_from_contract_orders:
      frequency: 0
      max_executions: -1

Do we really need to create broker orders multiple times per second? Or check for breaks? Same for the other stack handler functions. I'm testing now with all the stack handler methods running once a minute instead

  run_stack_handler:
    create_broker_orders_from_contract_orders:
      frequency: 1
      max_executions: -1

Any thoughts @robcarver17?