run_machine_concurrent_hot_reload devicelab test is flaky

Splitting this out from #14494 (since that's a closed PR for the implementation)... This happens intermittently:

NoSuchMethodError: The getter 'stdout' was called on null.

run:stdout: [{"event":"app.stop","params":{"appId":"c7777f51-f0a5-4273-a726-fe57345fa5c6"}}]
run:stdout: [   +2 ms] "flutter run" took 57,615ms.
run:stderr: Unhandled exception:
run:stderr: NoSuchMethodError: The getter 'stdout' was called on null.
run:stderr: Receiver: null
run:stderr: Tried calling: stdout
run:stderr: #0      Object.noSuchMethod (dart:core-patch/dart:core/object_patch.dart:46)
run:stderr: #1      stdout (package:flutter_tools/src/base/io.dart:176)
run:stderr: #2      StdoutLogger.writeToStdOut (package:flutter_tools/src/base/logger.dart:92)
run:stderr: #3      StdoutLogger.printStatus (package:flutter_tools/src/base/logger.dart:87)
run:stderr: #4      VerboseLogger._emit (package:flutter_tools/src/base/logger.dart:244)
run:stderr: #5      VerboseLogger.printTrace (package:flutter_tools/src/base/logger.dart:207)
run:stderr: #6      _AppRunLogger.printTrace (package:flutter_tools/src/commands/daemon.dart:859)
run:stderr: #7      printTrace (package:flutter_tools/src/globals.dart:50)
run:stderr: #8      ResidentRunner._serviceProtocolDone (package:flutter_tools/src/resident_runner.dart:652)
run:stderr: #9      _rootRunUnary (dart:async/zone.dart:1134)
run:stderr: #10     _CustomZone.runUnary (dart:async/zone.dart:1031)
run:stderr: #11     _FutureListener.handleValue (dart:async/future_impl.dart:129)
run:stderr: #12     _Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:633)
run:stderr: #13     _Future._propagateToListeners (dart:async/future_impl.dart:662)
run:stderr: #14     _Future._complete (dart:async/future_impl.dart:467)
run:stderr: #15     _SyncCompleter.complete (dart:async/future_impl.dart:51)
run:stderr: #16     ChannelManager.listen. (package:json_rpc_2/src/channel_manager.dart:58)
run:stderr: #17     _rootRun (dart:async/zone.dart:1122)
run:stderr: #18     _CustomZone.run (dart:async/zone.dart:1023)
run:stderr: #19     _CustomZone.runGuarded (dart:async/zone.dart:925)
run:stderr: #20     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:383)
run:stderr: #21     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:393)
run:stderr: #22     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:277)
run:stderr: #23     _ForwardingStream._handleDone (dart:async/stream_pipe.dart:106)
run:stderr: #24     _ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:172)
run:stderr: #25     _rootRun (dart:async/zone.dart:1122)
run:stderr: #26     _CustomZone.run (dart:async/zone.dart:1023)
run:stderr: #27     _CustomZone.runGuarded (dart:async/zone.dart:925)
run:stderr: #28     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:383)
run:stderr: #29     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:393)
run:stderr: #30     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:277)
run:stderr: #31     _ForwardingStream._handleDone (dart:async/stream_pipe.dart:106)
run:stderr: #32     _ForwardingStreamSubscription._handleDone (dart:async/stream_pipe.dart:172)
run:stderr: #33     _rootRun (dart:async/zone.dart:1122)
run:stderr: #34     _CustomZone.run (dart:async/zone.dart:1023)
run:stderr: #35     _CustomZone.runGuarded (dart:async/zone.dart:925)
run:stderr: #36     _BufferingStreamSubscription._sendDone.sendDone (dart:async/stream_impl.dart:383)
run:stderr: #37     _BufferingStreamSubscription._sendDone (dart:async/stream_impl.dart:393)
run:stderr: #38     _BufferingStreamSubscription._close (dart:async/stream_impl.dart:277)
run:stderr: #39     _StreamController&&_SyncStreamControllerDispatch._sendDone (dart:async/stream_controller.dart:770)
run:stderr: #40     _StreamController._closeUnchecked (dart:async/stream_controller.dart:627)
run:stderr: #41     _StreamController.close (dart:async/stream_controller.dart:620)
run:stderr: #42     _rootRun (dart:async/zone.dart:1122)
run:stderr: #43     _CustomZone.run (dart:async/zone.dart:1023)
run:stderr: #44     _FutureListener.handleWhenComplete (dart:async/future_impl.dart:151)
run:stderr: #45     _Future._propagateToListeners.handleWhenCompleteCallback (dart:async/future_impl.dart:603)
run:stderr: #46     _Future._propagateToListeners (dart:async/future_impl.dart:659)
run:stderr: #47     _Future._completeWithValue (dart:async/future_impl.dart:477)
run:stderr: #48     _Future._asyncComplete. (dart:async/future_impl.dart:507)
run:stderr: #49     _rootRun (dart:async/zone.dart:1126)
run:stderr: #50     _CustomZone.run (dart:async/zone.dart:1023)
run:stderr: #51     _CustomZone.bindCallback. (dart:async/zone.dart:949)
run:stderr: #52     _microtaskLoop (dart:async/schedule_microtask.dart:41)
run:stderr: #53     _startMicrotaskLoop (dart:async/schedule_microtask.dart:50)
run:stderr: #54     _runPendingImmediateCallback (dart:isolate-patch/dart:isolate/isolate_patch.dart:112)
run:stderr: #55     _RawReceivePortImpl._handleMessage (dart:isolate-patch/dart:isolate/isolate_patch.dart:165)
exitcode: 255
Task failed: Received unexpected exit code 255 from run process.

@devoncarew

(from @devoncarew):

Looks like it's trying to print 'Service protocol connection closed.'. This call may be happening after we've torn down some of the app context / logging forwarding machinery. We may need to make this more robust in terms of writes after the app finishes, or choose to send the writes up to the higher-level handlers (would would probably just print to stdout).

But it looks like you're tickling an existing issue - this isn't new with your PR.

@tvolkert, @jcollins-g, is it expected that context[Stdio] can be null, or should that be updated to always return a value?

https://github.com/flutter/flutter/blob/master/packages/flutter_tools/lib/src/base/io.dart#L176

@tvolkert

(from @tvolkert):

context[Stdio] shouldn't be null:

flutter/packages/flutter_tools/lib/runner.dart

Line 68 in 0885866

context.putIfAbsent(Stdio, () => const Stdio());

@devoncarew

@devoncarew I've tried a bunch of times but can't repro this locally. I've tried looking through the code but can't really see any obvious issues (there is a condition in io.dart where it won't use context[Stdio] if context is null, instead using io.stdout but I don't know if that's happening here, I can't see any obvious reason why context would be null).

I'm happy to dig more, but I might need some more info on all this hangs together... Are there multiple processes on the host or just the VM running flutter run on the host and the VM running the app/observatory on the device? (If so, what's with the indirection/layers for stdout? presumably the Service protocol connection closed text is originating from the host side then the Observatory socket dies?)

@yjbanov

@yjbanov Is there any way to run unmerged code on the devicelab machines (eg. a branch?)? I can't repro this flaky test locally so not sure how to test things. For ex. removing the --verbose flag where the test runs flutter run ---machine might resolve it (or rather, side-step it) but it'd be good to test it without the long PR/review/merge cycles.

Unfortunately, as of today, there isn't a way to test unmerged changes in the lab without physical access to it.

I'd like to try a wild guess. Our mac machines have proven to be the flakiest machines in the lab. How about we try switching from mac/android to linux/android? If that doesn't help we can investigate further.

@devoncarew

We could try; though I suspect this is a legit race condition so while that might (by fluke) resolve the flakiness I'm not sure if it's a good fix.

@devoncarew WDYT? I did try to repro on my MacBook but no joy there either - ran it 10-15 times and every one passed.

@DanTup

I have seen other evidence of context[SomethingValid] returning null inexplicably. While in my case I fixed it in another way, I agree with @DanTup that this isn't something we should sweep under the rug in the general case. I wasn't able to reproduce mine even with the lab though, so you've got some possibilities here I didn't.

To flush out any bugs like this I proposed doing something quite complicated, but regardless I think instrumenting context with some old fashioned printf-debugging could lead to figuring out what's really happening here.

Yeah, this is why I was hoping to be able to run it without merging it to master so we can just litter it with debugging code. Seems like that's non-trivial though and adding enough logging to track down without exposing it to the user (or risking breaking something) might also be tricky?

I also thought about trying to tweak the test runner so I can run it on a loop on my MacBook to see if it crashes with a larger number of runs (leave it running overnight or something). If I could repro locally (even infrequently) it would be significantly easier to debug.

I don't suppose anyone else could give it a couple of runs locally on the off chance another machine/device combination might see it?

Also - are these tests being randomly assigned agents? Can we tell if it's a specific machine/device failing?

I'm looking at this again; still can't repro.. however, I spotted something maybe interesting...

In the stack for the error we have:

 ResidentRunner._serviceProtocolDone (package:flutter_tools/src/resident_runner.dart:652)

This is where the print is originating that's failing. There's a comment in that file:

flutter/packages/flutter_tools/lib/src/resident_runner.dart

Lines 636 to 642 in f914e70

    
           // This hooks up callbacks for when the connection stops in the future. 
        
           // We don't want to wait for them. We don't handle errors in those callbacks' 
        
           // futures either because they just print to logger and is not critical. 
        
           service.done.then<Null>( // ignore: unawaited_futures 
        
             _serviceProtocolDone, 
        
             onError: _serviceProtocolError 
        
           ).whenComplete(_serviceDisconnected);

The comment suggests that this might be a known race - trying to write output while things are being torn down. It seems like the plan is that any errors during these methods are ignored. So, my question is - why are they being surfaced? The futures aren't awaited, so why aren't their errors silently ignored?

FWIW - I don't actually see any output that says Service protocol connection closed when I run the tests here, which also seems a little strange?

(Is it reasonable to stick a .catchError that does nothing on the end?)

The comment suggests to me that they don't catch them because the logger will print the error for us, not that they will be ignored. I think you're on to something with the race though. Seems likely that something is going down during teardown where we are trying to print, the context is non-null, but also doesn't have Stdio set. It might also explain the problem I fixed with incomplete understanding in #14401 (I didn't even have a stack trace to go on in that one).

If that's the case, you might try rearranging the code to handle things in a manner similar to this -- making it so that there's a default implementation Stdio even if context is not null but has no Stdio.

Ideally such a hack should go inside the context object itself rather than how I did it, but without being able to catch the code "in the act" with a debugger and gaining some more understanding, I'd be wary of depending on anything going on inside the context object -- after all, this shouldn't be happening!

@jcollins-g

+1 to @jcollins-g

There's also this method of defaulting a DI'd class.

@tvolkert

I would be careful with @tvolkert's suggestion: in the event of a similar initialization race (where we try to print something before the context is fully initialized for some reason), that method would take precedence over putIfAbsent() calls in whatever initializer is setting up the context. So, it might have unintended consequences.

Ok, I'm still rather unsure what I should try here :(

Though before putting shotgun fixes into "production" code to debug this, is anyone able to repro this (dart bin/run.dart -t run_machine_concurrent_hot_reload) locally, or get physical access to the devicelab machine (the flaky runs all seem to be on device usb:4245815296X product:athene model:Moto_G__4_ device:athene transport_id:1)?

I could potentially get physical access to the devicelab machine. But I probably wouldn't have time until the week after next.

Exploring all our options:

Have someone with physical access to the devicelab try to debug this.
Modify the device lab in such a way as to allow testing unmerged changes on it (ideally with --runs-per-test=<some_large_number>).
Finding a way to reproduce locally (I couldn't).
Changing our devicelab tests to run with -v, and instrumenting flutter_tools code with a bunch of new printTrace() statements. It's akin to checking debug statements into production code, but it'd only affect those running in verbose mode.

Any other options I'm missing?

I can't think of any other options. I think 1 is simplest for this case but I think 2 is useful long-term.

@yjbanov

@yjbanov talked this through in person, and I think the underlying cause is #15352

@tvolkert

@tvolkert @yjbanov Test hasn't failed/flaked since this was pushed. How long should I gix it before marking it as not flaky? (I noticed there are some others marked flakey but are entirely green as far as the dashboard goes, so not sure what you normally do).

@DanTup

@DanTup we should remove the flaky marker for this and the others that are green (the others are tests that have been fixed but that people forgot to mark as non-flaky).

Ok, I've opened #15443 - please check the comments and lmk if you want me to merge.

This thread has been automatically locked since there has not been any recent activity after it was closed. If you are still experiencing a similar issue, please open a new bug, including the output of flutter doctor -v and a minimal reproduction of the issue.

Navigation Menu

Repository navigation

run_machine_concurrent_hot_reload devicelab test is flaky #14636

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	// This hooks up callbacks for when the connection stops in the future.
	// We don't want to wait for them. We don't handle errors in those callbacks'
	// futures either because they just print to logger and is not critical.
	service.done.then<Null>( // ignore: unawaited_futures
	_serviceProtocolDone,
	onError: _serviceProtocolError
	).whenComplete(_serviceDisconnected);

run_machine_concurrent_hot_reload devicelab test is flaky #14636

Description

Activity

DanTup commented on Feb 12, 2018

DanTup commented on Feb 12, 2018

DanTup commented on Feb 12, 2018

DanTup commented on Feb 13, 2018

yjbanov commented on Feb 13, 2018

DanTup commented on Feb 14, 2018

jcollins-g commented on Feb 16, 2018

DanTup commented on Feb 16, 2018

DanTup commented on Feb 20, 2018

jcollins-g commented on Feb 20, 2018

tvolkert commented on Feb 20, 2018

jcollins-g commented on Feb 20, 2018

DanTup commented on Feb 21, 2018

tvolkert commented on Feb 23, 2018

DanTup commented on Feb 26, 2018

tvolkert commented on Mar 9, 2018

DanTup commented on Mar 12, 2018

tvolkert commented on Mar 12, 2018

DanTup commented on Mar 12, 2018

github-actions commented on Sep 3, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions