1.49.4 / Plex / Internal Errors on Google Drive

VBB · October 9, 2019, 4:54pm

Update: Started running build 180 yesterday around 9 am. No errors all day with light streaming activity. Initiated Plex scan around 8 pm after priming the mount, and it seemed fine for a few minutes until I noticed that there was no more activity in the Plex live scan log. After a while, the scan continued, but then Plex just crashed. This doesn't happen very often, if at all, so I'm not sure what to blame. There were no errors in the Rclone mount log. Plex issued several server updates yesterday, including one late last night, so that could have had something to do with it. After the crash, I went ahead and installed that latest release (1913), installed Windows Server 2016 updates, and rebooted. Then I started a fresh mount (still build 180), primed it, and started another Plex scan. When I checked this morning, everything was fine. No Plex crash, no mount errors.

TL;DR - I need another 24 hours for a final verdict on build 180

ncw · October 9, 2019, 5:00pm

Thank you for testing!

thestigma · October 9, 2019, 5:12pm

Just want to report - I tried the latest beta build as of late last night (CET) (forgot to note exact version, sorry!)
and I saw more stalling and the same internal error problem in my readout there.
It happened a few hours into a moderate but consistent load of manually hashing a bunch of smaller files via mount.

I apologize for not copying the exact version and error, but I working on a different thing at the time so it wasn't really at the front of my mind. I will make sure to log properly next beta-fix I test for this problem

ncw · October 9, 2019, 9:03pm

@thestigma this is the one I'd really like testing

thestigma · October 9, 2019, 9:05pm

Will try that now then.

(I updated that other bug thread on the vfs cache btw)

EDIT: Got a full stall with this version fairly quickly. Unfortunately had my log set to NOTICE rather than INFO, but observed behaviour seemed consistent with the error we have seen before.
I am re-testing now with log level INFO to attempt to confirm more solidly.

VBB · October 10, 2019, 4:12am

Unfortunately, I have to report the same as @thestigma. After running fine for almost an entire day, this happened again:

2019/10/08 22:04:23 NOTICE: Serving remote control on http://127.0.0.1:5572/
The service rclone has been started.
2019/10/09 19:16:04 INFO : Google drive root 'crypt': Change notify listener failure: Get https://www.googleapis.com/drive/v3/changes?alt=json&fields=nextPageToken%2CnewStartPageToken%2Cchanges(fileId%2Cfile(name%2Cparents%2CmimeType))&includeItemsFromAllDrives=true&pageSize=1000&pageToken=791464&prettyPrint=false&supportsAllDrives=true: stream error: stream ID 719; INTERNAL_ERROR

Stalled the Plex scan and crashed the software. What I noticed yesterday already was that when this happens, the rclone.exe stays at a constant 27-30% CPU and I have to kill it in order to kill the Plex executable. As long as the Rclone mount is still up and running, I cannot even "end task" on Plex. It won't do anything, but once I stop the mount, Plex also quits. Hope that all makes some sense.

ncw · October 10, 2019, 6:54am

If you could kill -QUIT the rclone process at this point then post the entire backtrace that would be very helpful. I'll be able to see what rclone is doing at that point.

VBB · October 10, 2019, 3:47pm

Sorry, when I said I have to kill rclone, I meant doing a CTRL+C on the mount window, which is the same thing I do to stop the mount normally anyway. Rclone itself doesn't seem to hang or crash, but it's causing Plex to crash during a scan for some reason.

ncw · October 10, 2019, 7:27pm

If you do a CTRL-\ instead of CTRL-C yo'll get a very long backtrace. It would be helpful if you could post that - then I can see why rclone is using 30% of the CPU - it might be an important clue!

thestigma · October 10, 2019, 10:09pm

Interesting! Very useful to know about.

I've (as you know) been a bit busy with other versions over the last few days, but I will return to this now and keep an eye out for that CPU-overuse issue if I see further stalls. I don't use Plex, so it would be nice to see if that has anything to do with it or if it seems to be a consistent thing tied directly to the recent go-version problems.

I haven't experienced any crashes BTW. Rclone just stops attempting transfers seemingly (what I refer to as stalling). I didn't note any issue closing it down normally. I assume this is pretty similar to what VBB is describing. Plex crashing as a result is probably just because it's expecting responses that never come.

asdffdsa · October 10, 2019, 10:10pm

yes, very interesting.

@ncw , if you can send me a list of ctrl+ keystrokes, i will make a wiki out of it..

ncw · October 11, 2019, 6:31am

CTRL-\ only works on unix based systems (Linux/macOS/BSD not windows). It is a standard key to send a QUIT signal to the running process. The Go runtime interprets it to mean stop but produce a backtrace of what you are doing. It is very useful for debugging.

CTRL-C sends an INT signal to stop the process.

CTRL-T sends a INFO signal (macOS only). That will cause rclone to print stats which is generally what that key is used for in macOS. Linux/Windows don't have this keystroke.

@asdffdsa maybe these should be in the docs somewhere rather than the wiki? Fancy sending a pull request for that?

asdffdsa · October 11, 2019, 4:04pm

@thestigma can you explain to me how do a pull request to update the documentation?

thestigma · October 11, 2019, 4:24pm

I'm no github veteran, so rather than me clumsily trying to explain something I have a poor grasp of, it's better you just read this short guide on it:
https://help.github.com/en/articles/creating-a-pull-request

Finding the document or code-file you wanted to edit is often tricky if you aren't familiar with the structure (which I am not really either), but assuming that you wanted to put this on the general rclone "usage" page then I think it is this one:

github.com

rclone/rclone/blob/master/docs/content/docs.md

---
title: "Documentation"
description: "Rclone Usage"
date: "2019-02-25"
---

Configure
---------

First, you'll need to configure rclone.  As the object storage systems
have quite complicated authentication these are kept in a config file.
(See the `--config` entry for how to find the config file and choose
its location.)

The easiest way to make the config is to run rclone with the config
option:

    rclone config

See the following for detailed instructions for

This file has been truncated. show original

Not sure what other place would be appropriate for it?

ncw · October 13, 2019, 11:22am

Did you get a stall with DEBUG? Getting a log with debug will be very interesting! It is probably very big though and contains private data so if you want to email it to nick@craig-wood.com or a link that is fine (put a link to this forum post in!).

My feeling about this bug is that it is

something to do with http2 and drive
possibly a problem at drive they will fix
possibly a problem in the go standard library that will get fixed eventually

Unfortunately I don't have enough info to be reporting bugs upstream so a log with -vv would be extremely helpful even if it is enormous.

I can't release v1.50 which is otherwise ready to go without resolving this...

thestigma · October 13, 2019, 3:07pm

Sorry Nick, I kind of got distracted on other issues (which required me to run other versions).

But I can try to make this a priority for the next day or two (however long it takes) to get that debug log to you if you consider it a priority.

Just to make sure we don't waste time - please verify for me if if we are still working on the same build. Just re-link it preferably, and I'll start some intensive testing on it.

EDIT:
Ok, this one is now running with full debug-log, on the same hashing workload I've seen stalls on before. I will leave running overnight as needed to induce failure.

rclone v1.49.5-180-gea304f41-fix-http2-retry-beta

os/arch: windows/amd64
go version: go1.13.1

(Note to self, test start 14.okt 00:00)

ncw · October 14, 2019, 8:13am

That is perfect thanks!

If we can't get to the bottom of this in the few days I'm going to release v1.50 compiled with go1.12. This isn't ideal since people will compile their own with go1.13 but I don't want to hold up the release indefinitely.

thestigma · October 14, 2019, 2:26pm

About 16 hrs testing continously so far (except maybe a couple of hrs during the morning)
No stalls so far... but this issue has proven to hard to recreate and a bit random.
Testing continues for now, just wanted to give an update...

EDIT: test passed 24hrs now - still no problem.
I'll probably leave it another night, but assuming I don't wake up to an error - how long do you want me to run this for @NCW ?

ncw · October 15, 2019, 7:23am

That is good.

How long can you run it for? Another day or two?

Could you send me the log so far (without stopping rclone)?

thestigma · October 15, 2019, 1:04pm

Test now going on 39hrs. No hard stall yet, but I haven't need trying to follow the log either...

For you baby, anything! chuu! <3

Sure, it's a massive thing at 750MB so good luck... thankfully zips to 23,3MB. I've dispatched to your gmail now.
(for the future, can you accept rar format also? Better compression due to larger dictionary size)