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

Add basic logging functionality & log all connection metrics #24

Merged
merged 2 commits into from
Dec 30, 2021

Conversation

AndrewPardoe
Copy link
Contributor

commit 3c1b750
Author: Andrew Pardoe AndrewPardoe@users.noreply.github.com
Date: Fri Dec 24 09:13:15 2021 -0800

Add basic logging and connection logging

Add new logging options:
  - tmo_logfile: specify logfile
  - tmo_log_all: log all connection statistics

Also move some error output to logfile

commit fd85144
Author: Andrew Pardoe AndrewPardoe@users.noreply.github.com
Date: Tue Dec 21 16:23:51 2021 -0500

Add default operational logging

1. Move error messages from print to logging.error
2. Add operational logging
3. Add log_all option to log all connection characteristics

commit cb5eefd
Author: Andrew Pardoe AndrewPardoe@users.noreply.github.com
Date: Mon Dec 20 22:25:43 2021 -0500

Added logging for basic cases

commit 3c1b750
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Fri Dec 24 09:13:15 2021 -0800

    Add basic logging and connection logging

    Add new logging options:
      - tmo_logfile: specify logfile
      - tmo_log_all: log all connection statistics

    Also move some error output to logfile

commit fd85144
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Tue Dec 21 16:23:51 2021 -0500

    Add default operational logging

    1. Move error messages from print to logging.error
    2. Add operational logging
    3. Add log_all option to log all connection characteristics

commit cb5eefd
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Mon Dec 20 22:25:43 2021 -0500

    Added logging for basic cases
@AndrewPardoe
Copy link
Contributor Author

Example log file, collected on both Windows and WSL/Ubuntu:

2021/12/24 09:18:00 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 66 ms | Uptime: 734696 sec
2021/12/24 09:18:08 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 127 ms | Uptime: 734703 sec
2021/12/24 09:18:12 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 53 ms | Uptime: 734707 sec
2021/12/24 09:18:15 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 188 ms | Uptime: 734710 sec
2021/12/24 09:18:21 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 70 ms | Uptime: 734717 sec
2021/12/24 09:18:24 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 157 ms | Uptime: 734720 sec
2021/12/24 09:18:28 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 63 ms | Uptime: 734724 sec

This logfile is for a normal, no-event run. If there had been an event (failed ping, reboot, etc.) that also gets logged.

Next step is to just log deltas. I'd like to read the log, check for changes, then log only if there are changes. Then I think I'm done with my changes :)

Example with timestamps replaced by line numbers for illustration:

1: [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 53 ms | Uptime: 734707 sec
2: [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 188 ms | Uptime: 734710 sec
3: [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 70 ms | Uptime: 101 sec
4: [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 805 ms | Uptime: 7101 sec
5: [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 98 ms | Uptime: 12489 sec

1: Baseline
2: 4G moved from B2 to B66
3: Uptime decreased, meaning there was a reboot for some reason
4: Average ping latency over threshold (maybe 10x?)
5: 4G moved from B66 back to B2

@AndrewPardoe
Copy link
Contributor Author

AndrewPardoe commented Dec 24, 2021

Sigh. After a record uptime of over 8 days, my modem decided to give you a good demonstration of a logfile with an actual reboot.

Note the -1 ms ping: I changed the ping detection logic to return -1 ms for a failed series of pings and the actual average ping time for success.

2021/12/24 09:34:41 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 76 ms | Uptime: 735696 sec
2021/12/24 09:35:43 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 95 ms | Uptime: 735758 sec
2021/12/24 09:36:45 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 102 ms | Uptime: 735820 sec
2021/12/24 09:37:50 [ERROR] Could not ping google.com.
2021/12/24 09:37:50 [INFO] Reboot requested.
2021/12/24 09:37:50 [INFO] Rebooting.
2021/12/24 09:37:53 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: -1 ms | Uptime: 735886 sec
2021/12/24 09:38:55 [CRITICAL] Could not post login request, exiting.
2021/12/24 09:38:55 [CRITICAL] Could not query site info, exiting.
2021/12/24 09:39:57 [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 86 ms | Uptime: 98 sec
2021/12/24 09:40:58 [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 79 ms | Uptime: 159 sec
2021/12/24 09:41:59 [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 89 ms | Uptime: 220 sec
2021/12/24 09:43:01 [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 74 ms | Uptime: 282 sec
2021/12/24 09:44:03 [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 75 ms | Uptime: 344 sec
2021/12/24 09:45:05 [INFO] 4G: B66 |  5G: n41 | eNB ID: 178935 | Avg Ping: 78 ms | Uptime: 406 sec

@AndrewPardoe
Copy link
Contributor Author

Delta logging as described above is in the delta branch. I'm testing it out on my system for a while.

@highvolt-dev
Copy link
Owner

Looks great, thanks for your continued contributions, @AndrewPardoe - let me know when you feel you've tested this enough to merge!

@highvolt-dev
Copy link
Owner

highvolt-dev commented Dec 28, 2021

Relates to #11 #12 #17

commit 4cc7fa6
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Tue Dec 28 07:56:53 2021 -0800

    Cleanup small delta logging items

commit 22d1c60
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Mon Dec 27 07:58:36 2021 -0800

    Add option to force log write from command line

    This option's nice when you're watching your log like a boiling pot

commit 83bc382
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Sun Dec 26 08:58:36 2021 -0800

    Correct indentation error: `data` out of scope

commit c05700d
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Sun Dec 26 08:47:04 2021 -0800

    Update requirements for tailer & parse

commit e31d079
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Sun Dec 26 08:42:41 2021 -0800

    Add delta logging
@AndrewPardoe
Copy link
Contributor Author

OK, I'm done. I've got all the edits I need for my usage. The script's been running a few days on my server.

Note that the delta logging pulls in two more requirements: tail and parse. I can do these things in straight Python if you prefer.

Feel free to merge. Thanks!

@AndrewPardoe
Copy link
Contributor Author

Example log for delta logging. I used the command-line parameter --log-all a few times when logging in to check on the server.

2021/12/26 09:00:13 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 93 ms | Uptime: 42478 sec
2021/12/26 10:18:15 [INFO] Ping ms 364, over 3x 93 ms
2021/12/26 10:18:15 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 364 ms | Uptime: 47161 sec
2021/12/27 08:00:28 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 74 ms | Uptime: 125294 sec
2021/12/27 17:03:44 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 50 ms | Uptime: 157890 sec
2021/12/28 04:30:52 [CRITICAL] Could not post login request, exiting.
2021/12/28 04:30:52 [CRITICAL] Could not query site info, exiting.
2021/12/28 07:34:00 [INFO] 4G: B2 |  5G: n41 | eNB ID: 178935 | Avg Ping: 59 ms | Uptime: 210106 sec

@highvolt-dev highvolt-dev linked an issue Dec 30, 2021 that may be closed by this pull request
Copy link
Owner

@highvolt-dev highvolt-dev left a comment

Choose a reason for hiding this comment

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

Probably want to update the README, add command line flags for any missing options like the log file location, and refactor the repetitive msg printing and logging code with a helper function, but this looks solid. Thanks for contributing upstream!

if ping_index > 0:
time.sleep(ping_interval)
ping_exec = subprocess.run(ping_cmd, capture_output=True)
print(ping_exec.stdout.decode('utf-8'))
if is_win and 'Destination host unreachable' in str(ping_exec.stdout):
Copy link
Owner

Choose a reason for hiding this comment

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

https://stackoverflow.com/questions/2953462/pinging-servers-in-python#comment69975395_32684938

On Windows, ping has a clean exit status when "Destination host unreachable" is encountered and needs to specifically be called out to return -1 here for ping_time.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I changed the ping logic significantly. It ignores the return code on Windows in favor of searching for the ping time, but it's easy enough to put that check back in.

      if ping_exec.returncode != 0:
        return -1
      pattern = b'[rtt|round-trip] min/avg/max/mdev = \d+.\d+/(\d+.\d+)/\d+.\d+/\d+.\d+ ms'
      if is_win:
        pattern = b'Minimum = \d+ms, Maximum = \d+ms, Average = (\d+)ms'
      ping_ms = re.search(pattern, ping_exec.stdout)

sys.exit(2)
if self.skip_reboot:
for var in {'ping', '4G_band', '5G_band', 'enbid'}:
self.reboot[var] = False
# if not self.login['username']:
Copy link
Owner

Choose a reason for hiding this comment

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

I do want to eventually be sure to log this error when there is not a TTY attached, so I'll want to create an issue to track this

Copy link
Contributor Author

Choose a reason for hiding this comment

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

OK, I'll ignore this for now.

@highvolt-dev highvolt-dev merged commit ae9d264 into highvolt-dev:main Dec 30, 2021
@highvolt-dev
Copy link
Owner

@AndrewPardoe feel free to implement the few things I just noted (e.g. README), but I can get around to this if not!

AndrewPardoe added a commit to AndrewPardoe/tmo-monitor that referenced this pull request Dec 31, 2021
Squashed commit of the following:

commit b1a388c4364ddf5998c93d431c8bd77c367680d9
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Fri Dec 31 09:50:27 2021 -0800

    Add print_and_log function

commit fe673487bde3ca3768a67ef633bc09595b95f6d3
Author: Andrew Pardoe <AndrewPardoe@users.noreply.github.com>
Date:   Fri Dec 31 09:21:29 2021 -0800

    Add logging options to command line & README

    Also add back early ping success check for Windows.
highvolt-dev added a commit that referenced this pull request Dec 31, 2021
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.

Version 2 Beta Feedback
2 participants