Determine difference in behavior for logging on Win vs Mac

[PropGit]

On Windows, there is a definite difference in behavior in logging in comparison to what is logged in Mac.

The next two log listings are from the same version (v0.5.4) of BlocklyPropClient, performing the same steps, downloading the same BlocklyProp project to a Propeller, and all done within about 1 minute of time.

On Windows, there are no repetitive logged events for COM port enumeration, no indication that the Connect button was clicked (no service starting messages), no logged activity of download processes being performed, and no logged activity of debug sessions:

2017-03-08 10:12:36,657 - blockly - INFO - Logger has been started.
2017-03-08 10:12:36,657 - blockly.main - INFO - Creating logger.
2017-03-08 10:12:37,095 - blockly - DEBUG - FTDI module load state
2017-03-08 10:12:37,095 - blockly - DEBUG - FTDIBUS      USB Serial Converter D USB Serial Converter D Kernel        Manual     Stopped
2017-03-08 10:12:37,180 - blockly.main - INFO - Logging is enabled
2017-03-08 10:12:37,180 - blockly.main - INFO - Application launched from C:\Program Files (x86)\BlocklyPropClient
2017-03-08 10:12:37,180 - blockly.main - INFO - Operating system is nt
2017-03-08 10:12:37,190 - blockly.main - INFO - Initializing the UI
2017-03-08 10:12:37,214 - blockly.main - INFO - Client IP is: 10.10.20.129
2017-03-08 10:12:37,214 - blockly.main - INFO - Port number is: 6009
2017-03-08 10:12:37,216 - blockly.main - INFO - Disk log file location is: C:\Users\jmartin.ROCKLIN/AppData/Local/Parallax/BlocklyPropClient.log
2017-03-08 10:12:37,219 - blockly.main - INFO - Initializing the UI menu
2017-03-08 10:12:38,854 - blockly.main - INFO - Connect state is: False

On Mac, there are repetitive logged events for COM port enumeration (don't think that's ideal, but it shows that there's activity), shows logged activity of download processes being performed, and also logged activity of debug sessions:

2017-03-08 10:28:36,612 - blockly - INFO - Logger has been started.
2017-03-08 10:28:36,612 - blockly.main - INFO - Creating logger.
2017-03-08 10:28:36,612 - blockly - INFO - FTDI driver is installed
2017-03-08 10:28:36,681 - blockly - DEBUG - FTDI module load state
2017-03-08 10:28:36,682 - blockly - DEBUG -   107    0 0xffffff7f80d56000 0x7000     0x7000     com.FTDI.driver.FTDIUSBSerialDriver (2.3) ECC3AF36-431D-370D-86F2-5237785E9CF8 <88 50 5 4 3 1>

2017-03-08 10:28:36,869 - blockly.main - INFO - Logging is enabled
2017-03-08 10:28:36,869 - blockly.main - INFO - Application launched from /Applications/BlocklyPropClient.app/Contents/MacOS
2017-03-08 10:28:36,870 - blockly.main - INFO - Operating system is posix
2017-03-08 10:28:36,870 - blockly.main - INFO - Initializing the UI
2017-03-08 10:28:41,894 - blockly.main - INFO - Client IP is: 0.0.0.0
2017-03-08 10:28:41,894 - blockly.main - INFO - Port number is: 6009
2017-03-08 10:28:41,894 - blockly.main - INFO - Disk log file location is: /Users/jmartin/Library/Logs/Parallax/BlocklyPropClient.log
2017-03-08 10:28:41,897 - blockly.main - INFO - Initializing the UI menu
2017-03-08 10:28:45,229 - blockly.main - INFO - Connect state is: False
2017-03-08 10:28:45,245 - blockly.server - INFO - Server starting
2017-03-08 10:28:45,253 - blockly.server - INFO - Creating server logger.
2017-03-08 10:28:45,253 - blockly.server - DEBUG - Application started from: /Applications/BlocklyPropClient.app/Contents/MacOS
2017-03-08 10:28:46,615 - blockly.server - DEBUG - Server poll received
2017-03-08 10:28:46,624 - blockly.server - DEBUG - Port list retreived
2017-03-08 10:28:46,625 - blockly.loader - INFO - Getting ports
2017-03-08 10:28:46,625 - blockly.loader - INFO - Enumerating host ports
2017-03-08 10:28:46,630 - blockly.loader - DEBUG - Port count: 2
2017-03-08 10:28:46,631 - blockly.server - DEBUG - Port /dev/cu.Bluetooth-Incoming-Port discovered.
2017-03-08 10:28:46,632 - blockly.server - DEBUG - Port /dev/cu.usbserial-WX9S5M0 discovered.
2017-03-08 10:28:50,425 - blockly.server - DEBUG - Writing program payload to temp file.
2017-03-08 10:28:50,429 - blockly.server - DEBUG - /var/folders/70/sj5kbq6j7k3_76ccdvhk59gh0000gn/T/tmp_l5LLV.elf saved.
2017-03-08 10:28:50,429 - blockly.server - DEBUG - Loading program to device.
2017-03-08 10:28:50,429 - blockly.loader - DEBUG - Loader executable path is: /Applications/BlocklyPropClient.app/Contents/MacOS/propeller-tools/mac/propeller-load)
2017-03-08 10:28:50,430 - blockly.loader - DEBUG - Loader commandline is: ['/Applications/BlocklyPropClient.app/Contents/MacOS/propeller-tools/mac/propeller-load', '-r']
2017-03-08 10:28:50,430 - blockly.loader - INFO - Talking to com port.
2017-03-08 10:28:50,430 - blockly.loader - INFO - Executing process ['/Applications/BlocklyPropClient.app/Contents/MacOS/propeller-tools/mac/propeller-load', '-r', '-p', '/dev/cu.usbserial-WX9S5M0', '/var/folders/70/sj5kbq6j7k3_76ccdvhk59gh0000gn/T/tmp_l5LLV.elf']
2017-03-08 10:28:51,630 - blockly.server - DEBUG - Port list retreived
2017-03-08 10:28:51,631 - blockly.loader - INFO - Getting ports
2017-03-08 10:28:51,631 - blockly.server - DEBUG - Port /dev/cu.Bluetooth-Incoming-Port discovered.
2017-03-08 10:28:51,631 - blockly.server - DEBUG - Port /dev/cu.usbserial-WX9S5M0 discovered.
2017-03-08 10:28:52,978 - blockly.loader - INFO - Load result is: 0
2017-03-08 10:28:52,978 - blockly.loader - DEBUG - Load error string: 
2017-03-08 10:28:52,978 - blockly.loader - DEBUG - Load output string: Propeller Version 1 on /dev/cu.usbserial-WX9S5M0
Loading /var/folders/70/sj5kbq6j7k3_76ccdvhk59gh0000gn/T/tmp_l5LLV.elf to hub memory
8220 bytes remaining             
7196 bytes remaining             
6172 bytes remaining             
5148 bytes remaining             
4124 bytes remaining             
3100 bytes remaining             
2076 bytes remaining             
1052 bytes remaining             
28 bytes remaining             
                               
8220 bytes sent
Verifying RAM ... OK

2017-03-08 10:28:52,978 - blockly.server - INFO - Application load complete.
2017-03-08 10:28:52,991 - blockly.serial - INFO - Creating serial logger.
2017-03-08 10:28:53,604 - blockly.serial - INFO - Message received
2017-03-08 10:28:53,605 - blockly.serial - DEBUG - Message is: +++ open port /dev/cu.usbserial-WX9S5M0 115200
2017-03-08 10:28:53,605 - blockly.serial - DEBUG - Connection config string: /dev/cu.usbserial-WX9S5M0 115200
2017-03-08 10:28:53,605 - blockly.serial - DEBUG - Setting serial port config: Port /dev/cu.usbserial-WX9S5M0, Speed 115200
2017-03-08 10:28:53,605 - blockly.serial - INFO - Opening serial port /dev/cu.usbserial-WX9S5M0
2017-03-08 10:28:53,624 - blockly.serial - INFO - Serial port /dev/cu.usbserial-WX9S5M0 is open.
2017-03-08 10:28:53,625 - blockly - DEBUG - Polling serial port.
2017-03-08 10:28:54,129 - blockly - DEBUG - Data received from device: Hello
2017-03-08 10:28:55,136 - blockly - DEBUG - Data received from device: Hello
2017-03-08 10:28:56,019 - blockly.serial - INFO - Closing serial port
2017-03-08 10:28:56,628 - blockly.server - DEBUG - Port list retreived
2017-03-08 10:28:56,628 - blockly.loader - INFO - Getting ports
2017-03-08 10:28:56,629 - blockly.loader - INFO - Enumerating host ports
2017-03-08 10:28:56,631 - blockly.loader - DEBUG - Port count: 2
2017-03-08 10:28:56,631 - blockly.server - DEBUG - Port /dev/cu.Bluetooth-Incoming-Port discovered.
2017-03-08 10:28:56,631 - blockly.server - DEBUG - Port /dev/cu.usbserial-WX9S5M0 discovered.
2017-03-08 10:29:00,869 - blockly.main - INFO - Connect state is: True
2017-03-08 10:29:00,870 - blockly.main - DEBUG - Terminating server process
2017-03-08 10:29:02,610 - blockly.server - DEBUG - Port list retreived
2017-03-08 10:29:02,611 - blockly.loader - INFO - Getting ports
2017-03-08 10:29:02,611 - blockly.loader - INFO - Enumerating host ports
2017-03-08 10:29:02,614 - blockly.loader - DEBUG - Port count: 2
2017-03-08 10:29:02,614 - blockly.server - DEBUG - Port /dev/cu.Bluetooth-Incoming-Port discovered.
2017-03-08 10:29:02,615 - blockly.server - DEBUG - Port /dev/cu.usbserial-WX9S5M0 discovered.

[zfi]

The execution path for Windows is unique in some areas of the code. Sine the initial emphasis for the detailed logging was to identify gross logic errors in the MacOS path, very little Windows-specific code was given the logging treatment. This certainly can be corrected but it's not a priority.

The double logging in the Linux/MacOS code paths is likely caused by defining more that one logger. The log events are sent to all listening loggers, so there must be two loggers listening to the events.