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

Added debug messages and use the logging framework for stdout #178

Merged
merged 5 commits into from
Apr 2, 2017

Conversation

douglaz
Copy link
Contributor

@douglaz douglaz commented Jan 23, 2017

This PR makes the following changes:

  • Add a --debug flag to enable a timestamped view of output
  • Add debug messages for instance launching and ssh connection

I tested this PR by launching a cluster. Output sample:

2017-01-23 20:34:50,008 Requesting 101 spot instances at a max price of $0.04...
2017-01-23 20:34:50,675 0 of 101 instances granted. Waiting...
2017-01-23 20:35:21,182 All 101 instances granted.
2017-01-23 20:35:39,665 72 instances not in state running, like: ['i-0ff168f921510cf35', 'i-05cabf994eb94dba8', 'i-039411476cc0bd181'] ...
2017-01-23 20:35:44,000 5 instances not in state running, like: ['i-02fc1fb06deb09384', 'i-01333c5213535b208', 'i-072986101dade82f9'] ...
2017-01-23 20:35:48,085 5 instances not in state running, like: ['i-02fc1fb06deb09384', 'i-01333c5213535b208', 'i-072986101dade82f9'] ...
2017-01-23 20:35:52,124 2 instances not in state running, like: ['i-072986101dade82f9', 'i-0dbc7b19682a2b0d6'] ...
2017-01-23 20:37:02,079 [54.237.237.187] SSH got an exception: [Errno None] Unable to connect to port 22 on 54.237.237.187
2017-01-23 20:37:02,781 [107.23.122.133] SSH online.

Fixes #177.
Helps #47 (I'm not sure it completely solves it).

Copy link
Owner

@nchammas nchammas left a comment

Choose a reason for hiding this comment

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

Thank you for taking this on @douglaz and going through the code to find good candidates for conversion. I do not have extensive experience with logger so I will defer to your judgement on a few things here.

Is the idea to convert all print() statements over to logger? If not, what is the rule or heuristic for when something should remain a print()?

Looks like you need to rebase the PR btw.

flintrock/ec2.py Outdated
@@ -785,7 +785,7 @@ def _create_instances(
if spot_requests:
request_ids = [r['SpotInstanceRequestId'] for r in spot_requests]
if any([r['State'] != 'active' for r in spot_requests]):
logger.info("Canceling spot instance requests...", file=sys.stderr)
print("Canceling spot instance requests...", file=sys.stderr)
Copy link
Owner

Choose a reason for hiding this comment

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

Why did you revert this logger statement?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Because it doesn't work. When you call a log, you can't decide where it will go. You need to configure on log creation where the output will be (stdout, stderr, file or a combination of all this...)

flintrock/ec2.py Outdated
@@ -121,6 +125,12 @@ def wait_for_state(self, state: str):
ec2 = boto3.resource(service_name='ec2', region_name=self.region)

while any([i.state['Name'] != state for i in self.instances]):
if logger.isEnabledFor(logging.DEBUG):
waiting_instances = [i for i in self.instances if i.state['Name'] != state]
sample_size = 3
Copy link
Owner

Choose a reason for hiding this comment

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

Don't see the need for this variable. I think [:3] on the next line is OK.

flintrock/ec2.py Outdated
waiting_instances = [i for i in self.instances if i.state['Name'] != state]
sample_size = 3
sample = [i.id for i in waiting_instances][:sample_size]
logger.debug('{size} instances not in state {state}, like: {sample} ...'.format(size=len(waiting_instances), state=state, sample=sample))
Copy link
Owner

Choose a reason for hiding this comment

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

Formatting nitpick: It's awkward to have a closed list followed by ellipses. We should also quote keywords to distinguish them from prose.

e.g.:

72 instances not in state 'running': 'i-0ff168f921510cf35', 'i-05cabf994eb94dba8', 'i-039411476cc0bd181', ...

@@ -38,6 +39,9 @@
THIS_DIR = os.path.dirname(os.path.realpath(__file__))


logger = logging.getLogger('flintrock')
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 not too familiar with logging, but judging from the pattern, shouldn't this be logging.getLogger('flintrock.flintrock')?

flintrock/ssh.py Outdated
break
except socket.timeout as e:
logger.debug("[{h}] SSH got a timeout...".format(h=host))
Copy link
Owner

Choose a reason for hiding this comment

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

I would prefer these messages to be without the "got a". So simply:

  • "SSH timeout."
  • "SSH exception: ..."
  • "SSH AuthenticationException."

@click.group()
@click.option(
'--config',
help="Path to a Flintrock configuration file.",
default=get_config_file())
@click.option('--provider', default='ec2', type=click.Choice(['ec2']))
@click.version_option(version=__version__)
# TODO: implement some solution like in https://github.com/pallets/click/issues/108
@click.option('--debug/--no-debug', default=False, help="Whether to show debug messages")
Copy link
Owner

Choose a reason for hiding this comment

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

For consistency with the other help messages, I prefer: "Show debug information."

@douglaz
Copy link
Contributor Author

douglaz commented Mar 1, 2017

@nchammas ideally everything would use logging. I kept all stderr prints because you can't make some logging calls go to stdout and others to stderr. Perhaps we can configure a stderr_logger to use in those cases. I'll try that later.

@douglaz
Copy link
Contributor Author

douglaz commented Mar 13, 2017

@nchammas Please take a look. Regarding stdout/stderr. I think we can't customize it by call. We can configure for everything go to stdout or to stderr, but not some messages to stdout and others to stderr. All stderr messages are still using print.

Now the log with --debug is formatted as this:

2017-03-13 19:04:02,125 - flintrock.ec2       - INFO  - Requesting 2 spot instances at a max price of $0.13...
2017-03-13 19:04:02,582 - flintrock.ec2       - INFO  - 0 of 2 instances granted. Waiting...
2017-03-13 19:04:32,743 - flintrock.ec2       - INFO  - All 2 instances granted.
2017-03-13 19:04:46,127 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:04:46,127 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:04:51,133 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:04:51,133 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:04:56,139 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:04:56,139 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:01,145 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:05:01,145 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:06,150 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:05:06,150 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:11,156 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:05:11,157 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:16,162 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:05:16,162 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:21,168 - flintrock.ssh       - DEBUG - [52.87.156.178] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.156.178
2017-03-13 19:05:21,168 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:26,174 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:26,363 - flintrock.ssh       - INFO  - [52.87.156.178] SSH online.
2017-03-13 19:05:26,585 - flintrock.core      - INFO  - [52.87.156.178] Configuring ephemeral storage...
2017-03-13 19:05:31,179 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:36,185 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:41,191 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:46,197 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:51,203 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:05:52,241 - flintrock.services  - INFO  - [52.87.156.178] Installing HDFS...
2017-03-13 19:05:56,204 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:01,205 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:05,347 - flintrock.services  - INFO  - [52.87.156.178] Installing Spark...
2017-03-13 19:06:06,206 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:11,207 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:16,209 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:21,210 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:26,211 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:31,212 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:36,213 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:41,214 - flintrock.ssh       - DEBUG - [52.87.162.127] SSH exception: [Errno None] Unable to connect to port 22 on 52.87.162.127
2017-03-13 19:06:46,416 - flintrock.ssh       - INFO  - [52.87.162.127] SSH online.
2017-03-13 19:06:46,912 - flintrock.core      - INFO  - [52.87.162.127] Configuring ephemeral storage...
2017-03-13 19:07:04,908 - flintrock.services  - INFO  - [52.87.162.127] Installing HDFS...
2017-03-13 19:07:13,110 - flintrock.services  - INFO  - [52.87.162.127] Installing Spark...
2017-03-13 19:07:41,192 - flintrock.services  - INFO  - [52.87.156.178] Configuring HDFS master...
2017-03-13 19:08:01,049 - flintrock.services  - INFO  - [52.87.156.178] Configuring Spark master...
2017-03-13 19:08:29,423 - flintrock.services  - INFO  - HDFS online.
2017-03-13 19:08:29,536 - flintrock.services  - INFO  - Spark Health Report:
  * Master: ALIVE
  * Workers: 1
  * Cores: 2
  * Memory: 13.9 GB    
2017-03-13 19:08:29,545 - flintrock.ec2       - INFO  - launch finished in 0:04:30.

@douglaz
Copy link
Contributor Author

douglaz commented Mar 13, 2017

Also this:

2017-03-13 20:52:45,473 - flintrock.ec2       - INFO  - All 16 instances granted.
2017-03-13 20:53:02,038 - flintrock.ec2       - DEBUG - 10 instances not in state 'running': 'i-095d39e27feee81a5', 'i-0774a5bf2ddde8a89', 'i-01a9e3301cdf9a486', ...

@@ -161,15 +161,17 @@ def get_config_file() -> str:


def configure_log(debug: bool):
handler = logging.StreamHandler()
root_logger = logging.getLogger('flintrock')
import sys
Copy link
Owner

Choose a reason for hiding this comment

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

Do we need this? sys is already imported at the top of the file.

@nchammas
Copy link
Owner

Thanks for sharing the sample output. Looks really neat! 👍

In addition to my minor review comment, we also need to add debug to the config template. We want all command-line options to be reflected in the config template.

I think with those 2 changes in place I'll be able to merge this in.

@douglaz
Copy link
Contributor Author

douglaz commented Mar 23, 2017

@nchammas please review the changes

@nchammas nchammas merged commit 818fa91 into nchammas:master Apr 2, 2017
@nchammas
Copy link
Owner

nchammas commented Apr 2, 2017

I tested this out and it looks good to me! Thanks for working on this @douglaz.

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