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

Make mock test server emit timing data #5891

Merged
merged 4 commits into from Jun 5, 2018

Conversation

Projects
None yet
2 participants
@wisechengyi
Copy link
Contributor

wisechengyi commented Jun 1, 2018

addresses #5752

@@ -127,7 +128,7 @@ impl Drop for TestServer {
#[derive(Clone, Debug)]
pub struct MockResponder {
mock_execution: MockExecution,
received_messages: Arc<Mutex<Vec<(String, Box<protobuf::Message>)>>>,
pub received_messages: Arc<Mutex<Vec<(String, Box<protobuf::Message>, SystemTime)>>>,

This comment has been minimized.

@wisechengyi

wisechengyi Jun 1, 2018

Contributor

@illicitonion is it okay to make it pub? same as above

This comment has been minimized.

@illicitonion

illicitonion Jun 1, 2018

Contributor

Works for me :)

@@ -143,7 +144,7 @@ impl MockResponder {
.received_messages
.lock()
.unwrap()
.push((message.descriptor().name().to_string(), Box::new(message)));
.push((message.descriptor().name().to_string(), Box::new(message), SystemTime::now()));

This comment has been minimized.

@wisechengyi

wisechengyi Jun 1, 2018

Contributor

Is this the right place to record the timestamp when server receives the request?

This comment has been minimized.

@illicitonion

illicitonion Jun 1, 2018

Contributor

Looks good :)


// let (s, m, t) = messages.get(0).unwrap();
println!("{:?}", mock_server.mock_responder.received_messages);
// println!("{:?}", messages.get(1).unwrap().2.duration_since(messages.get(0).unwrap().2).unwrap());

This comment has been minimized.

@wisechengyi

wisechengyi Jun 1, 2018

Contributor

Currently

assert!(messages.len() == 2);

passes, but

println!("{:?}",  messages.get(1).unwrap().2.duration_since(messages.get(0).unwrap().2).unwrap());

prints

Duration { secs: 0, nanos: 1218000 }

which does not seem correct. we know line 1250 proves the backoff works, so not sure what I am missing here.

This comment has been minimized.

@illicitonion

illicitonion Jun 1, 2018

Contributor

Excitingly, this is pointing out a real bug!

The bug is that the logic currently reads:

If the response says the operation is not finished:
  Call GetOperation from the server
  Check whether we need to timeout or delay
  If we need to timeout, timeout
  If we need to delay, delay, then loop again

Where the logic should actually read:

If the response says the operation is not finished:
  Check whether we need to timeout or delay
  If we need to timeout, timeout
  If we need to delay, delay, then:
    Call GetOperation from the server, and loop

I'm not sure how I missed this in the original review!

If you move the code:

let grpc_result = map_grpc_result(operations_client.get().get_operation(&operation_request));
let operation = try_future!(grpc_result);

from where it currently is into the and_then block after the Delay, it will Just Work.

(We can then rewrite that block as:

future::done(map_grpc_result(operations_client.get().get_operation(&operation_request)))
                                .map(move |operation| future::Loop::Continue((operation, iter_num + 1)))
                                .to_boxed()

which is maybe a little cleaner?)

This comment has been minimized.

@wisechengyi

wisechengyi Jun 5, 2018

Contributor

Thanks for the pointer! Corrected

@illicitonion
Copy link
Contributor

illicitonion left a comment

Looks good!

On reading around std::time::SystemTime to work out what was going on here, I'm pretty sure we should be using std::time::Instant everywhere we're using std::time::SystemTime, both in the code you're adding, and in the existing code.

@@ -127,7 +128,7 @@ impl Drop for TestServer {
#[derive(Clone, Debug)]
pub struct MockResponder {
mock_execution: MockExecution,
received_messages: Arc<Mutex<Vec<(String, Box<protobuf::Message>)>>>,
pub received_messages: Arc<Mutex<Vec<(String, Box<protobuf::Message>, SystemTime)>>>,

This comment has been minimized.

@illicitonion

illicitonion Jun 1, 2018

Contributor

Works for me :)

@@ -143,7 +144,7 @@ impl MockResponder {
.received_messages
.lock()
.unwrap()
.push((message.descriptor().name().to_string(), Box::new(message)));
.push((message.descriptor().name().to_string(), Box::new(message), SystemTime::now()));

This comment has been minimized.

@illicitonion

illicitonion Jun 1, 2018

Contributor

Looks good :)


// let (s, m, t) = messages.get(0).unwrap();
println!("{:?}", mock_server.mock_responder.received_messages);
// println!("{:?}", messages.get(1).unwrap().2.duration_since(messages.get(0).unwrap().2).unwrap());

This comment has been minimized.

@illicitonion

illicitonion Jun 1, 2018

Contributor

Excitingly, this is pointing out a real bug!

The bug is that the logic currently reads:

If the response says the operation is not finished:
  Call GetOperation from the server
  Check whether we need to timeout or delay
  If we need to timeout, timeout
  If we need to delay, delay, then loop again

Where the logic should actually read:

If the response says the operation is not finished:
  Check whether we need to timeout or delay
  If we need to timeout, timeout
  If we need to delay, delay, then:
    Call GetOperation from the server, and loop

I'm not sure how I missed this in the original review!

If you move the code:

let grpc_result = map_grpc_result(operations_client.get().get_operation(&operation_request));
let operation = try_future!(grpc_result);

from where it currently is into the and_then block after the Delay, it will Just Work.

(We can then rewrite that block as:

future::done(map_grpc_result(operations_client.get().get_operation(&operation_request)))
                                .map(move |operation| future::Loop::Continue((operation, iter_num + 1)))
                                .to_boxed()

which is maybe a little cleaner?)

@wisechengyi wisechengyi force-pushed the wisechengyi:5752 branch from b6117bb to 513a267 Jun 5, 2018

message.descriptor().name().to_string(),
Box::new(message),
Instant::now(),
));

This comment has been minimized.

@wisechengyi

wisechengyi Jun 5, 2018

Contributor

no change here, just fmt. somehow the formatter doesn't like the existing format :/


// let (s, m, t) = messages.get(0).unwrap();
println!("{:?}", mock_server.mock_responder.received_messages);
// println!("{:?}", messages.get(1).unwrap().2.duration_since(messages.get(0).unwrap().2).unwrap());

This comment has been minimized.

@wisechengyi

wisechengyi Jun 5, 2018

Contributor

Thanks for the pointer! Corrected

@wisechengyi

This comment has been minimized.

Copy link
Contributor

wisechengyi commented Jun 5, 2018

Also converted SystemTime to Instant

@wisechengyi wisechengyi changed the title wip for #5752 Make mock test server emit timing data Jun 5, 2018

@illicitonion
Copy link
Contributor

illicitonion left a comment

Looks great, thanks!

@illicitonion illicitonion merged commit 4c7425d into pantsbuild:master Jun 5, 2018

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment