flaky test: pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test

[jmesserly]

@@@STEP_TEXT@ 82% +261 -0 @­@@
Running "vm" command: xcodebuild/ReleaseIA32/dart-sdk/bin/dart --ignore-unrecognized-flags --enable_asserts --enable_type_checks --package-root=xcodebuild/ReleaseIA32/packages/ /Volumes/data/b/build/slave/pub-mac/build/dart/sdk/lib/_internal/pub/test/pubspec_test.dart

FAILED: none-vm-checked release_ia32 pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test
Expected: pass
Actual: fail
CommandOutput[vm]:

stdout:
unittest-suite-wait-for-done
FAIL: with an expired credentials.json, refreshes and saves the refreshed access token to credentials.json
  Caught The schedule had 2 errors:
  ScheduleError: "Process 'pub lish' ended earlier than scheduled with exit code 69."
  Stack trace:
  | dart:async _createTimer.<fn>
  | timer_impl.dart 96:21 _Timer._createTimerHandler._handleTimeout
  | timer_impl.dart 112:23 _Timer._createTimerHandler.<fn>
  | dart:isolate _ReceivePortImpl._handleMessage
  
  Error detected during task in queue "tasks":
  * creating directory:
  | sdk
  | '-- version
  * creating directory:
  | myapp
  | |-- async descriptor
  | |-- LICENSE
  | '-- lib
  | '-- test_pkg.dart
  * starting 'scheduled server 0'
  * #­3
  * starting process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * writing 'y' to stdin for process 'pub lish'
  > 'scheduled server 0' waiting for POST /token
  |
  | Stack trace:
  | | package:scheduled_test/scheduled_server.dart 77:13 ScheduledServer.handle
  | | sdk/lib/_internal/pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test.dart 30:18 main.<fn>
  | | sdk/lib/_internal/pub/test/test_pub.dart 340:9 _integration.<fn>
  | | dart:async _createTimer.<fn>
  | | timer_impl.dart 96:21 _Timer._createTimerHandler._handleTimeout
  | | timer_impl.dart 112:23 _Timer._createTimerHandler.<fn>
  | | dart:isolate _ReceivePortImpl._handleMessage
  * 'scheduled server 0' waiting for GET /api/packages/versions/new
  * waiting for process 'pub lish' to exit
  * #­16
  
  Pending out-of-band callbacks:
  * waiting to reach shouldExit() or kill() for process 'pub lish'
  |
  | Stack trace:
  | | dart:async _createTimer.<fn>
  | | timer_impl.dart 96:21 _Timer._createTimerHandler._handleTimeout
  | | timer_impl.dart 112:23 _Timer._createTimerHandler.<fn>
  | | dart:isolate _ReceivePortImpl._handleMessage
  ================================================================================
  ScheduleError: "The schedule timed out after 0:00:05.000000 of inactivity."
  Stack trace:
  | dart:async _createTimer.<fn>
  | timer_impl.dart 96:21 _Timer._createTimerHandler._handleTimeout
  | timer_impl.dart 112:23 _Timer._createTimerHandler.<fn>
  | dart:isolate _ReceivePortImpl._handleMessage
  
  Error detected during task in queue "tasks":
  * creating directory:
  | sdk
  | '-- version
  * creating directory:
  | myapp
  | |-- async descriptor
  | |-- LICENSE
  | '-- lib
  | '-- test_pkg.dart
  * starting 'scheduled server 0'
  * #­3
  * starting process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * reading the next stdout line from process 'pub lish'
  * writing 'y' to stdin for process 'pub lish'
  > 'scheduled server 0' waiting for POST /token
  |
  | Stack trace:
  | | package:scheduled_test/scheduled_server.dart 77:13 ScheduledServer.handle
  | | sdk/lib/_internal/pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test.dart 30:18 main.<fn>
  | | sdk/lib/_internal/pub/test/test_pub.dart 340:9 _integration.<fn>
  | | dart:async _createTimer.<fn>
  | | timer_impl.dart 96:21 _Timer._createTimerHandler._handleTimeout
  | | timer_impl.dart 112:23 _Timer._createTimerHandler.<fn>
  | | dart:isolate _ReceivePortImpl._handleMessage
  * 'scheduled server 0' waiting for GET /api/packages/versions/new
  * waiting for process 'pub lish' to exit
  * #­16
  ================================================================================
  
  Debug info:
  Results of running 'pub lish':
  Process exited with exit code 69.
  Standard output:
  | MSG : Publishing "test_pkg" 1.0.0:
  | | |-- LICENSE
  | | |-- lib
  | | | '-- test_pkg.dart
  | | '-- pubspec.yaml
  | |
  | MSG : Looks great! Are you ready to upload your package (y/n)?
  | Uploading...
  Standard error:
  | FINE: Using DART_SDK to find SDK at /tmp/temp_dir1_xobgXA/sdk
  | FINE: Pub 0.1.2+3
  | IO : Spawning git --version
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp/lib.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp/lib:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib/test_pkg.dart
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib
  | | /private/tmp/temp_dir1_xobgXA/myapp/LICENSE
  | | /private/tmp/temp_dir1_xobgXA/myapp/pubspec.yaml
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp/lib.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp/lib:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib/test_pkg.dart
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib
  | | /private/tmp/temp_dir1_xobgXA/myapp/LICENSE
  | | /private/tmp/temp_dir1_xobgXA/myapp/pubspec.yaml
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp.
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp/lib.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp/lib:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib/test_pkg.dart
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib
  | | /private/tmp/temp_dir1_xobgXA/myapp/LICENSE
  | | /private/tmp/temp_dir1_xobgXA/myapp/pubspec.yaml
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib
  | | /private/tmp/temp_dir1_xobgXA/myapp/LICENSE
  | | /private/tmp/temp_dir1_xobgXA/myapp/pubspec.yaml
  | IO : Finished git. Exit code 0.stdout:git version 1.7.4.1Nothing output on stderr.
  | FINE: Determined git command git.
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp.
  | IO : Listing directory /private/tmp/temp_dir1_xobgXA/myapp/lib.
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp/lib:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib/test_pkg.dart
  | FINE: Listed directory /private/tmp/temp_dir1_xobgXA/myapp:
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib
  | | /private/tmp/temp_dir1_xobgXA/myapp/LICENSE
  | | /private/tmp/temp_dir1_xobgXA/myapp/pubspec.yaml
  | FINE: Archiving and publishing test_pkg 1.0.0 (/private/tmp/temp_dir1_xobgXA/myapp).
  | FINE: Creating .tag.gz stream containing:
  | | /private/tmp/temp_dir1_xobgXA/myapp/LICENSE
  | | /private/tmp/temp_dir1_xobgXA/myapp/pubspec.yaml
  | | /private/tmp/temp_dir1_xobgXA/myapp/lib/test_pkg.dart
  | |
  | IO : Spawning tar --create --gzip --directory /private/tmp/temp_dir1_xobgXA/myapp LICENSE pubspec.yaml lib/test_pkg.dart
  | FINE: Showing confirm message: Looks great! Are you ready to upload your package
  | FINE: Loading OAuth2 credentials.
  | FINE: Saving OAuth2 credentials.
  | FINE: Ensuring directory /tmp/temp_dir1_xobgXA/cache exists.
  | IO : Writing 195 characters to text file /tmp/temp_dir1_xobgXA/cache/credentials.json.
  | FINE: HTTP POST http://localhost:65136/token
  | | content-type: application/x-www-form-urlencoded; charset=utf-8
  | |
  | | Body fields:
  | | grant_type: refresh_token
  | | refresh_token: <censored>
  | | client_id: 818368855108-8grd2eg9tj9f38os6f1urbcvsq399u8n.apps.googleusercontent.com
  | | client_secret: SWeqj8seoJW0w7_CpEPFLX0K
  | | scope: https://www.googleapis.com/auth/userinfo.email
  | FINE: Saving OAuth2 credentials.
  | FINE: Ensuring directory /tmp/temp_dir1_xobgXA/cache exists.
  | IO : Writing 195 characters to text file /tmp/temp_dir1_xobgXA/cache/credentials.json.
  | FINE: Clean up system cache temp directory /tmp/temp_dir1_xobgXA/cache/_temp.
  | ERR :
  | FINE: #­0 PubHttpClient.send.<anonymous closure> (file:///Volumes/data/b/build/slave/pub-mac/build/dart/sdk/lib/_internal/pub/lib/src/http.dart:102:7)
  | | #­1 _CatchErrorFuture._zonedSendError (dart:async/future_impl.dart:409:24)
  | | #­2 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­3 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­4 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­5 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­6 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­7 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­8 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­9 _ThenFuture._zonedSendError (dart:async/future_impl.dart:380:14)
  | | #­10 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­11 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­12 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­13 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­14 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­15 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­16 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­17 _ThenFuture._zonedSendError (dart:async/future_impl.dart:380:14)
  | | #­18 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­19 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­20 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­21 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­22 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­23 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­24 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­25 _ThenFuture._zonedSendError (dart:async/future_impl.dart:380:14)
  | | #­26 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­27 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­28 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­29 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­30 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­31 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­32 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­33 _ThenFuture._zonedSendError (dart:async/future_impl.dart:380:14)
  | | #­34 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­35 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­36 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­37 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­38 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­39 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­40 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­41 _FutureImpl._chain (dart:async/future_impl.dart:288:23)
  | | #­42 _FutureImpl._setOrChainValue (dart:async/future_impl.dart:328:27)
  | | #­43 _SubscribeFuture._zonedSendError (dart:async/future_impl.dart:432:21)
  | | #­44 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­45 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­46 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­47 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­48 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­49 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­50 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­51 _ThenFuture._zonedSendError (dart:async/future_impl.dart:380:14)
  | | #­52 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­53 _ZoneBase._runInZone (dart:async/zone.dart:74:15)
  | | #­54 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­55 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­56 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­57 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­58 _FutureImpl._setError (dart:async/future_impl.dart:189:23)
  | | #­59 _ThenFuture._zonedSendError (dart:async/future_impl.dart:380:14)
  | | #­60 _TransformFuture._sendError.<anonymous closure> (dart:async/future_impl.dart:351:48)
  | | #­61 _ZoneBase._runInZone (dart:async/zone.dart:82:17)
  | | #­62 _ZoneBase._runUnguarded (dart:async/zone.dart:102:22)
  | | #­63 _ZoneBase.executeCallback (dart:async/zone.dart:58:23)
  | | #­64 _TransformFuture._sendError (dart:async/future_impl.dart:351:26)
  | | #­65 _FutureImpl._setErrorUnchecked (dart:async/future_impl.dart:211:26)
  | | #­66 _FutureImpl._asyncSetError.<anonymous closure> (dart:async/future_impl.dart:225:25)
  | | #­67 _asyncRunCallback (dart:async/event_loop.dart:9:15)
  | | #­68 _createTimer.<anonymous closure> (dart:async-patch/timer_patch.dart:8:13)
  | | #­69 _Timer._createTimerHandler._handleTimeout (timer_impl.dart:96:21)
  | | #­70 _Timer._createTimerHandler.<anonymous closure> (timer_impl.dart:112:23)
  | | #­71 _ReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:81:92)
  | |

0 PASSED, 1 FAILED, 0 ERRORS

stderr:
Unhandled exception:
Exception: Some tests failed.

­0 SimpleConfiguration.onDone (package:unittest/src/simple_configuration.dart:204:9)

­1 _completeTests (package:unittest/unittest.dart:782:17)

­2 _runTest (package:unittest/unittest.dart:751:19)

­3 _nextTestCase (package:unittest/unittest.dart:658:11)

­4 _asyncRunCallback (dart:async/event_loop.dart:9:15)

­5 _asyncRunCallback (dart:async/event_loop.dart:13:7)

­6 _createTimer.<anonymous closure> (dart:async-patch/timer_patch.dart:8:13)

­7 _Timer._createTimerHandler._handleTimeout (timer_impl.dart:96:21)

­8 _Timer._createTimerHandler._handleTimeout (timer_impl.dart:104:7)

­9 _Timer._createTimerHandler._handleTimeout (timer_impl.dart:104:7)

­10 _Timer._createTimerHandler.<anonymous closure> (timer_impl.dart:112:23)

­11 _ReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:81:92)

Command[vm]: xcodebuild/ReleaseIA32/dart-sdk/bin/dart --ignore-unrecognized-flags --enable_asserts --enable_type_checks --package-root=xcodebuild/ReleaseIA32/packages/ /Volumes/data/b/build/slave/pub-mac/build/dart/sdk/lib/_internal/pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test.dart
Took 0:00:06.625000

Short reproduction command (experimental):
    python tools/test.py -mrelease -t60 --checked --use-sdk pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test

Done none-vm-checked release_ia32 pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test: fail
@@@STEP_CLEAR@@@

[nex3]

The fundamental cause of this is the last error message printed by 'pub lish':

  | ERR :
  | FINE: #­0 PubHttpClient.send.<anonymous closure> (file:///Volumes/data/b/build/slave/pub-mac/build/dart/sdk/lib/_internal/pub/lib/src/http.dart:102:7)
  | | #­1 _CatchErrorFuture._zonedSendError (dart:async/future_impl.dart:409:24)
  | | ...

This is almost certainly some sort of dart:io bug. It's caught when sending a request with HttpClient, but the error message is blank, so it's hard to tell anything more.

---

Removed Area-Pub label.
Added Area-IO label.

[jmesserly]

ah, good call

[sgjesse]

I have tried to repro this by running the following:

xcodebuild/ReleaseIA32/dart loop.dart xcodebuild/ReleaseIA32/dart-sdk/bin/dart --ignore-unrecognized-flags --enable_asserts --enable_type_checks --package-root=xcodebuild/ReleaseIA32/packages/ sdk/lib/_internal/pub/test/oauth2/with_an_expired_credentials_refreshes_and_saves_test.dart

loop.dart contains:

mport 'dart:io';
import 'dart:async';
import 'dart:isolate';

void run() {
  port.receive((args, sendPort) {
    void run() {
      Process.run(args.first, args.skip(1).toList())
        .then((result) {
          print("Done");
          if (result.exitCode != 0) {
            sendPort.send(result);
            port.close();
          } else {
            run();
          }
        });
    }
    run();
  });
}

void main() {
  int count = 0;
  void spawn() {
    if (count == 4) return;
    count++;
    spawnFunction(run).call(new Options().arguments).then((result) {
      print(result.stdout);
      print(result.stderr);
      exit(1);
    });
    spawn();
  }
  spawn();
}

I did it on my laptop which is why only 4 isolates are started. However running it for a long time did not show any failure. Starting to many isolates create failures due to timeout.

First of all am I running the right thing?
Do you have any simpler repro of this?
Any insights to "when" this happens, e.g is it the first HTTP request send on the connection which fails?

---

Set owner to @whesse.
Added Accepted label.

[nex3]

As far as I know, no one's seen this outside of the bots, so there's no simpler repro available. It's hard to say what precisely triggers it, all the more so because the error message is blank. It is the first HTTP request made by that pub process, but there are many tests that make HTTP requests that haven't triggered this yet.

It's possible that there's something specific to the buildbots that's causing this. It may not reproduce locally.

[larsbak]

Added this to the M7 milestone.

[sgjesse]

Removed this from the M7 milestone.
Added this to the M8 milestone.

[whesse]

We just got this error on the buildbot, where the added code to debug this error printed something:
http://build.chromium.org/p/client.dart/builders/pub-win-be/builds/211/steps/pub%20tests/logs/stdio

[sgjesse]

From the log above this looks like an error communicating with a server. Judging from the error message the exception is a PubHttpException.

  | Error in PubHttpClient.send (issue #1) error: HTTP error 400: Bad Request
  | stacktrace: #­0 PubHttpClient.send (file:///E:/b/build/slave/pub-win-be/build/dart/sdk/lib/_internal/pub/lib/src/http.dart:60:7)
  | #­1 Client.send.<anonymous closure> (package:oauth2/src/client.dart:90:30)
  | #­2 _Future._propagateToListeners.<anonymous closure> (dart:async/future_impl.dart:449)
  | #­3 _rootRun (dart:async/zone.dart:510)
  | #­4 _ZoneDelegate.run (dart:async/zone.dart:323)
  | #­5 _CustomizedZone.run (dart:async/zone.dart:468)
  | #­6 _Future._propagateToListeners (dart:async/future_impl.dart:441)
  | #­7 _Future._complete (dart:async/future_impl.dart:298)
  | #­8 _Future._asyncComplete.<anonymous closure> (dart:async/future_impl.dart:354)
  | #­9 _asyncRunCallback (dart:async/event_loop.dart:18)
  | #­10 _createTimer.<anonymous closure> (dart:async-patch/timer_patch.dart:11)
  | #­11 _Timer._createTimerHandler._handleTimeout (timer_impl.dart:151)
  | #­12 _Timer._createTimerHandler.<anonymous closure> (timer_impl.dart:168)
  | #­13 _ReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:113)

[nex3]

The 404 error is expected -- note that the test that's failing is "package creation provides an error". The actual expectation that's failing is the exit code -- pub is expected to emit exit code 1 (due to the failure) but in fact emits exit code 0. It's unclear to me how that could happen.

[andersjohnsen]

Is still happening? We fixed a bug a few weeks ago, that would make passing test show up as failing.

Also, is this a mac-only issue?

---

Set owner to @Skabet.
Added NeedsInfo label.

[munificent]

I'm not sure if it's still happening. If you'd like, we can remove it from the status file and see how it goes.

[andersjohnsen]

Yeah, I think we should do that.

[munificent]

https://codereview.chromium.org/27260003/

[munificent]

OK, this is checked in now. Let's see how the bots like it.

---

Added Waiting label.

[sgjesse]

Added Fixed label.