oAuth2client: Callback never called with media upload because of retry logic and readStream

[Brmm]

Hello,

When trying to upload a media file to the youtube.videos.insert endpoint using a readStream, when receiving a 401 it will automatically retry the request, unfortunately the readStream has already been read, which result in never getting a callback from mikael/request.

The problem does not lie with the token but the actual service endpoint, youtube in this case, having bad permissions. Which is a problem that is solvable but I still like to have my callback invoked.

Is it possible to turn off the retry functionality in oauth2client.js? Retry logic will never work with readable streams imho.

const google = require('googleapis');
const youtube = google.youtube('v3');

const jwtClient = new google.auth.JWT(
  credentials.client_email,
  null,
  credentials.private_key,
  [
    'https://www.googleapis.com/auth/youtubepartner',
    'https://www.googleapis.com/auth/youtube',
    'https://www.googleapis.com/auth/youtube.force-ssl',
    'https://www.googleapis.com/auth/youtube.upload',
  ],
);

jwtClient.authorize((err) => {
  if(err) throw err;

  youtube.videos.insert({
    auth: jwtClient,
    onBehalfOfContentOwner: ownerId,
    onBehalfOfContentOwnerChannel: data.channelId,
    part: 'snippet, status',
    body: {
      snippet: {
        title: data.title,
        description: data.description,
        tags: '',
        categoryId: '',
      },
      status: {
        privacyStatus: 'private',
      },
    },
    resource: {
      name: 'test',
      mimeType: 'video/mp4',
    },
    media: {
      mimeType: 'video/mp4',
      body: fs.createReadStream(data.videoFilePath),
    },
  }, (err, resp) => {

    // this gets never called

    console.log('err', err);
    console.log('resp', resp);
  });
});

Current very dirty monkey patching solution:

const fs = require('fs');
const Stream = require('stream');
const google = require('googleapis');

google.auth.OAuth2.prototype._makeRequest = function (opts, callback) {
  if (opts.multipart) {
    opts.multipart = opts.multipart.map((params) => {
      if (params.body instanceof Stream.Readable) params.body = fs.createReadStream(params.body.path);
      return params;
    });
  }

  return this.transporter.request(opts, callback);
};

[JustinBeckwith]

I'm having trouble reproducing this one. This is the code I am using:

const google = require('googleapis');
const youtube = google.youtube('v3');
const credentials = require('./jwt.keys.json');
const fs = require('fs');

const FILENAME = './video.mov';

const jwtClient = new google.auth.JWT(
  credentials.client_email,
  null,
  credentials.private_key,
  [
    'https://www.googleapis.com/auth/youtubepartner',
    'https://www.googleapis.com/auth/youtube',
    'https://www.googleapis.com/auth/youtube.force-ssl',
    'https://www.googleapis.com/auth/youtube.upload',
  ],
);

jwtClient.authorize((err) => {
  if(err) throw err;

  var req = youtube.videos.insert({
    part: 'id,snippet,status',
    notifySubscribers: false,
    resource: {
      snippet: {
        title: 'Node.js YouTube Upload Test',
        description: 'Testing YouTube upload via Google APIs Node.js Client'
      },
      status: {
        privacyStatus: 'private'
      }
    },
    media: {
      body: fs.createReadStream(FILENAME)
    }
  }, function (err, data) {
    if (err) {
      console.error('ERROR!');
      console.error(err);
    }
    if (data) {
      console.log(util.inspect(data, false, null));
    }
    process.exit();
  });

  var fileSize = fs.statSync(FILENAME).size;

  // show some progress
  var id = setInterval(function () {
    var uploadedBytes = req.req.connection._bytesDispatched;
    var uploadedMBytes = uploadedBytes / 1000000;
    var progress = uploadedBytes > fileSize
      ? 100 : (uploadedBytes / fileSize) * 100;
    process.stdout.clearLine();
    process.stdout.cursorTo(0);
    process.stdout.write(uploadedMBytes.toFixed(2) + ' MBs uploaded. ' +
     progress.toFixed(2) + '% completed.');
    if (progress === 100) {
      process.stdout.write('\nDone uploading, waiting for response...\n');
      clearInterval(id);
    }
  }, 250);
});

And this is the output I get:

beckwith-macbookpro:171 beckwith$ node server.js 
3.24 MBs uploaded. 100.00% completed.
Done uploading, waiting for response...
ERROR!
{ Error: Login Required
    at new RequestError (/Users/beckwith/Code/171/node_modules/google-auth-library/lib/transporters.js:34:42)
    at Request._callback (/Users/beckwith/Code/171/node_modules/google-auth-library/lib/transporters.js:96:27)
    at Request.self.callback (/Users/beckwith/Code/171/node_modules/request/request.js:186:22)
    at emitTwo (events.js:126:13)
    at Request.emit (events.js:214:7)
    at Request.<anonymous> (/Users/beckwith/Code/171/node_modules/request/request.js:1163:10)
    at emitOne (events.js:116:13)
    at Request.emit (events.js:211:7)
    at IncomingMessage.<anonymous> (/Users/beckwith/Code/171/node_modules/request/request.js:1085:12)
    at Object.onceWrapper (events.js:313:30)
  code: 401,
  errors: 
   [ { domain: 'global',
       reason: 'required',
       message: 'Login Required',
       locationType: 'header',
       location: 'Authorization' } ] }

I'm surprised your callback is never invoked :( If you can provide a sample that runs entirely (with the exception of the video and the key file), it would be super helpful.

[Brmm]

Thank you for putting time into this. I realise it's an edge case and not easy to reproduce.

I found the culprit, the callback is not invoked when using the onBehalfOfContentOwner parameter. We need this because we're building a service that uploads videos to multiple channels with multiple content owners.

Note: the hanging only happens when the credentials have no access to the given content owner's profile (which is a Youtube Partner account), we are using a service account key created in the API console.

I assume something goes wrong when uploading the file, the credentials (the JWT) are correct but the service account has no access for the given content owner, the lib does a retry but the file stream has already been fully read. The retry logic uses the same stream instance which never dispatches an 'end' event anymore. Solution is to reset the read stream or create a new one like my ugly patch is doing, see my first comment.

const google = require('googleapis');
const youtube = google.youtube('v3');
const credentials = require('./jwt.keys.json');
const fs = require('fs');

const FILENAME = './video.mov';
const CHANNEL_ID = 'The_channel_id';
const CONTENT_OWNER_ID = 'The_content_owner_id';

const jwtClient = new google.auth.JWT(
  credentials.client_email,
  null,
  credentials.private_key,
  [
    'https://www.googleapis.com/auth/youtubepartner',
    'https://www.googleapis.com/auth/youtube',
    'https://www.googleapis.com/auth/youtube.force-ssl',
    'https://www.googleapis.com/auth/youtube.upload',
  ],
);

jwtClient.authorize((err) => {
  if (err) {
    console.log('auth error');
    throw err;
  }

  const req = youtube.videos.insert({
    auth: jwtClient,
    onBehalfOfContentOwner: CONTENT_OWNER_ID,
    onBehalfOfContentOwnerChannel: CHANNEL_ID,
    part: 'id,snippet,status',
    notifySubscribers: false,
    resource: {
      snippet: {
        title: 'Node.js YouTube Upload Test',
        description: 'Testing YouTube upload via Google APIs Node.js Client',
      },
      status: {
        privacyStatus: 'private',
      },
    },
    media: {
      body: fs.createReadStream(FILENAME),
    },
  }, (err, data) => {
    if (err) {
      console.error('Insert error!');
      console.error(err);
    }
    if (data) {
      console.log(util.inspect(data, false, null));
    }
    process.exit();
  });

  const fileSize = fs.statSync(FILENAME).size;

  // show some progress
  var id = setInterval(() => {
    const uploadedBytes = req.req.connection._bytesDispatched;
    const uploadedMBytes = uploadedBytes / 1000000;
    const progress = uploadedBytes > fileSize
      ? 100 : (uploadedBytes / fileSize) * 100;
    process.stdout.clearLine();
    process.stdout.cursorTo(0);
    process.stdout.write(`${uploadedMBytes.toFixed(2) } MBs uploaded. ${
      progress.toFixed(2) }% completed.`);
    if (progress === 100) {
      process.stdout.write('\nDone uploading, waiting for response...\n');
      clearInterval(id);
    }
  }, 250);
});

The output hangs:

$ node missing-callback-test.js
0.03 MBs uploaded. 100.00% completed.
Done uploading, waiting for response...

When the credentials are given access to the content owner's account we are successful:

0.03 MBs uploaded. 100.00% completed.
Done uploading, waiting for response...
{ [removed],
  status:
   { uploadStatus: 'uploaded',
     privacyStatus: 'private',
     license: 'youtube',
     embeddable: true,
     publicStatsViewable: true } }

Like said before this is a really rare edge case but we still lost some time figuring out why the callback is not invoked. Perhaps retry logic should not proceed for certain cases and just return the error from the backend?

Thank you again.

[AlisherNA]

Hello,
I keep videos on Firebase Storage. I'd like to move some videos to Youtube using FS Functions and Youtube API and node.js. I use Service Accounts to connect the Google servers.
When I take file from bucket and put to body, FS Logs show nothing. Why script doesn't insert video to youtube? Is it the same problem?
My code

/// file from Firebase Storage  
const vfile = bucket.file('/videos/test.MOV');

/// youtube function 
youtube.videos.insert({
            resource: {
                snippet: {
                    title: "Testing YoutTube API NodeJS module"
                  , description: "Test video upload via YouTube API"
                }
              , status: {
                    privacyStatus: "private"
                }
            }
          , part: "snippet,status"
          , media: {
                body: vfile.createReadStream()
            }
        }, (err, data) => {
            console.log("DONEinsert.",data);
			console.log("ERRORinsert.",err)
            process.exit();
        });

[JustinBeckwith]

@ofrobots I have an idea for this one, and I want to run it by you before submitting a PR. I don't think our current retry logic is at all useful.

Before the retry, all we really do is call refreshAccessToken(), which in turn calls refreshToken. If you look further up in the code, the call to getRequestMetadata made with every request already refreshes the token if needed.

I think the changes made in #242 likely negate the need for this retry logic at all. The retry only happens on 401/403 errors, which shouldn't happen as frequently with the new expiration window.

TL;DR - I want to get rid of this retry because I don't think it does anything useful, and it's causing problems.

Thoughts?

[ofrobots]

Yeah, the retry mechanism seems hokey, and unlikely to work for the stream case in general as @Brmm points out. It sounds reasonable to remove it, but isn't that going to be a semver major change? I guess the argument will have to be that the users will see no observable difference, and I am not fully convinced of that.

[JustinBeckwith]

I guess the argument will have to be that the users will see no observable difference

Except in this case, it's fixing a bug 🤣 I hear what you're saying though. Given the fact that this mostly causing problems with streaming requests - what do you think about just not retrying for those for now? Then I can file a 2.0 bug to eliminate the retry all together. Eh?

[ofrobots]

Except in this case, it's fixing a bug 🤣

To avoid being semver major we need to fix the bug without breaking other currently working code 😄.

Given the fact that this mostly causing problems with streaming requests - what do you think about just not retrying for those for now? Then I can file a 2.0 bug to eliminate the retry all together. Eh?

SGTM.