Flightlog logging bug/inconsistency when called via Satellite

Technical Help
#1

Flightlog behavior seems inconsistent/strange when called via Satellite; see example below to reproduce issue. Note that calling this code directly works fine, but not when using Satellite. Am I missing something or is this a bug?

Note that while this is a contrived example, I'm experiencing the same in production code when using Satellite to trade my moonshot strategies which have lots of Flightlog statements for debugging purposes.

# /codeload/test.py
import logging
from quantrocket.flightlog import FlightlogHandler


# Setup logger
logger = logging.getLogger('flighttest')
logger.setLevel(logging.DEBUG)
handler = FlightlogHandler()
logger.addHandler(handler)

def test_flightlog():
    for i in range(0, 10):
        logger.info(f'{i}. Flightlog test')
        print(f'{i}. Flightlog print test')
    return

Call with satellite: quantrocket satellite exec 'codeload.test.test_flightlog

I get the following output. Why did the print statements work, but only 1 of the logger.info statements?

jupyter:/codeload $ quantrocket flightlog stream -d
quantrocket_satellite_1|0. Flightlog print test
quantrocket_satellite_1|1. Flightlog print test
quantrocket_satellite_1|2. Flightlog print test
quantrocket_satellite_1|3. Flightlog print test
quantrocket_satellite_1|4. Flightlog print test
quantrocket_satellite_1|5. Flightlog print test
quantrocket_satellite_1|6. Flightlog print test
quantrocket_satellite_1|7. Flightlog print test
quantrocket_satellite_1|8. Flightlog print test
quantrocket_satellite_1|9. Flightlog print test
quantrocket_satellite_1|...The work of process 12225 is done. Seeya!
  quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:28:06 +0000] "POST /satellite/commands?cmd=codeload.test.test_flightlog HTTP/1.1" 200 22 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:28:06 flighttest: INFO 0. Flightlog test
  quantrocket_houston_1|172.18.0.17 - - [04/Sep/2021:05:28:06 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_satellite_1|worker 2 killed successfully (pid: 12225)
quantrocket_satellite_1|Respawned uWSGI worker 2 (new pid: 12261)

Here's the correct output if I call the script directly from Jupyter:

jupyter:/codeload $ quantrocket flightlog stream -d
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 0. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 1. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 2. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 3. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 4. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 5. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 6. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 7. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 8. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
quantrocket_flightlog_1|2021-09-04 01:31:41 flighttest: INFO 9. Flightlog test
quantrocket_houston_1|172.18.0.15 - - [04/Sep/2021:05:31:41 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
#2

Try:

handler = FlightlogHandler(background=False)

Flightlog logs in a background thread by default, and the satellite worker is recycling itself before the thread finishes.

#3

Hey @Brian, so this definitely fixed the issue at hand, but unfortunately I'm now seeing double logs for every call to logger.x; any idea what's going on here?

#6

Ok, I found that if I simply change handler = FlightlogHandler(background=False) across the board, this resolved my duplicate issue.

@Brian, do you see any issue with always using background = False? I'm sure it's more ideal to have the logger run on a background thread, but I'm not sure of a better way given the satellite issue.

Let me know; thanks mate!