Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rework logging #300

Draft
wants to merge 2 commits into
base: master
Choose a base branch
from
Draft

Rework logging #300

wants to merge 2 commits into from

Conversation

uzlonewolf
Copy link
Collaborator

I recently discovered another issue with having tons of devices. Like I mentioned in #208 (comment), I'm dumping a bunch of device sockets into select.select() just like the scanner does. Do you know what happens if you turn debug on and then poll the status of 52 devices simultaneously? It's... not pretty. So, I reworked the logging. Log messages now include the "name" of the source, which for devices is i.e. "tinytuya.OutletDevice.eb1######s". Initially I removed the red coloring of the text from the message, but then decided it was probably there for a reason and put it back. I did keep the device ID in cyan though. Red removed:
Screenshot from 2023-03-13 20-14-56 cropped

Red put back:
Screenshot from 2023-03-13 23-55-49 cropped

When I added the per-device debug toggle I also made its color selection independent (default is to match the global). I didn't intend it to be this way, but it worked out really well as it allows things like:
Screenshot from 2023-03-14 01-42-14 cropped

Anyway, I have this as a draft as it needs a *lot* more testing. I've only verified it works for basic functions.

@jasonacox
Copy link
Owner

I love this!!!

@@ -479,7 +488,6 @@ def parse_header(data):
#seqno |= unknown << 32
total_length = payload_len + header_len + len(SUFFIX_6699_BIN)
else:
#log.debug('Header prefix wrong! %08X != %08X', prefix, PREFIX_VALUE)
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While we are here, should we add a note?

# Tuya protocol should include a header prefix 0x55AA (3.1, 3.2, 3.3, 3.4) or 0x6699 (3.5) 
# (see https://github.com/jasonacox/tinytuya/discussions/260)

And instead of "Header prefix wrong!" - should we error out with "Header prefix unknown!" ? Not that Tuya would ever change that with the next protocol rev. 😉

Comment on lines +619 to +620
# FIXME: make a logger available here
#log.info( 'CF is: %r %r %r cool: %r %r %r', cf, self.heatto, heatto / 100, self.coolto, coolto / 100, self.time )
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FIXME - I'm sure you know, just adding to my review

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I'm not sure what I'm going to do about that one, it's buried like 3 classes deep. I may just remove it, though having a logger available there for debugging may be needed at some point.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sortof gross, but possibly define a global scoped log (glog) to use for this one?

Comment on lines 69 to 79
tinytuya.set_debug(debug, color)
#if debug:
# if color:
# logging.basicConfig( format="\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[39;2m%(message)s\x1b[0m", level=logging.DEBUG )
# else:
# logging.basicConfig( level=logging.DEBUG )

if state == 1:
from . import wizard
else:
from . import scanner
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm slow or tired or both... why do we want to defer? Does scanner log logic infect wizard?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll most likely remove that one and put it back like it was. I was doing a lot of experimenting and at one point tried to enable debugging before tinytuya was loaded to get the 2 version lines, but it ended up not working and I reverted most of it.

@@ -67,7 +67,7 @@
import struct
import sys
import time
from colorama import init
from colorama import init, Fore, Back, Style
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, love this!!!

tinytuya/core.py Outdated

if color:
# \x1b[39;2m
fmt = "\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[31;1m%(message)s\x1b[0m"
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I haven't tried, but wonder if we could leverage more colorama here instead to make it more readable. I mean, it's fine.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I originally wanted to but couldn't decide between a + b + '%(string)' + c +d (ugh) or doing %s%s%s%s%s%s while trying to get the % formatting to not mangle the embedded %'s (also ugh). I'll see if I can find a more-readable way that I'm happy with.

Copy link
Collaborator Author

@uzlonewolf uzlonewolf Mar 15, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, I think the choice is between
fmt = ''.join( (Style.RESET_ALL, Fore.RED, Style.BRIGHT, '%(levelname)s:', Style.NORMAL, '%(name)s:', Fore.RED, Style.BRIGHT, '%(message)s', Style.RESET_ALL) )
and
fmt = Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL

Any preference?

Copy link
Owner

@jasonacox jasonacox Mar 15, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer the second one (addition). Very simple. Also, I can't get the first one to work in my test.

TypeError: str.join() takes exactly one argument (10 given)

fmt = (Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' +
    Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL)

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, I forgot the parentheses around the list, should have been fmt = ''.join( (...) ). Oh well, we're using the additive one anyway.

While I was at it I rewrote termcolor() as well:

def termcolor(color=True):
    if color is False:
        # Disable Terminal Color Formatting
        bold = subbold = normal = dim = alert = alertdim = cyan = red = yellow = ""
    else:
        # Terminal Color Formatting
        bold     = Style.RESET_ALL + Fore.LIGHTWHITE_EX + Style.BRIGHT
        subbold  = Style.RESET_ALL + Fore.GREEN
        normal   = Style.RESET_ALL
        dim      = Style.RESET_ALL + Fore.LIGHTWHITE_EX + Style.DIM
        alert    = Style.RESET_ALL + Fore.LIGHTRED_EX + Style.BRIGHT
        alertdim = Style.RESET_ALL + Fore.LIGHTRED_EX + Style.DIM
        cyan     = Style.RESET_ALL + Fore.CYAN
        red      = Style.RESET_ALL + Fore.RED
        yellow   = Style.RESET_ALL + Fore.YELLOW
    return bold,subbold,normal,dim,alert,alertdim,cyan,red,yellow

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For join, we would need to make it into an array. I saw some post that join can be faster than addition, but it wasn't apparent to me and I still think the addition is cleaner:

from colorama import Fore, Style
import time 

print("\nJoin Method: ")
start = time.time()
for x in range(200):
    fmt = ''.join([Style.RESET_ALL, Fore.RED, Style.BRIGHT, '%(levelname)s:', Style.NORMAL, '%(name)s:', Fore.RED, Style.BRIGHT, '%(message)s', Style.RESET_ALL])
end = time.time()
print("The time difference is :", end - start)

print("\nAddition Method: ")
start = time.time()
for x in range(200):
    fmt = (Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL)
end = time.time()
print("The time difference is :", end - start)

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice! Yes, love the termcolor() update!

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Upping the loop count to 200,000 makes it a bit more obvious, but the difference is so minuscule it's not worth worrying about. I don't really care either way and currently have it as:

    if color:
        fmt = Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL
    else:
        fmt = "%(levelname)s:%(name)s:%(message)s"

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants