Ngrok fails to provide HTTPS tunnel within 3s

[vk5ztv]

When running in daemon mode, onedrived crashes after about 30 seconds and never syncs. Immediately after the crash, running with --debug reveals the following:

onedrived start --debug Starting onedrived ... OK [2017-02-05 00:43:13,201] DEBUG: MainThread: Starting new HTTPS connection (1): api.onedrive.com [2017-02-05 00:43:15,761] DEBUG: MainThread: https://api.onedrive.com:443 "GET /v1.0/drives HTTP/1.1" 200 378 [2017-02-05 00:43:15,783] DEBUG: MainThread: Refreshing repository session. [2017-02-05 00:43:15,784] DEBUG: MainThread: Starting new HTTPS connection (1): login.live.com [2017-02-05 00:43:18,214] DEBUG: MainThread: https://login.live.com:443 "POST /oauth20_token.srf HTTP/1.1" 200 1686 [2017-02-05 00:43:18,363] INFO: MainThread: Session for account d3838f8ebe5535a6 will expire in 3599 seconds. [2017-02-05 00:43:18,363] DEBUG: MainThread: Will refresh session in 3479 seconds. [2017-02-05 00:43:18,367] INFO: MainThread: Sweeping onedrived temporary files from local repositories. [2017-02-05 00:43:18,372] DEBUG: Worker-0: Started. [2017-02-05 00:43:18,373] DEBUG: Worker-1: Started. [2017-02-05 00:43:19,385] INFO: MainThread: Local ngrok API url: http://127.0.0.1:4045/api [2017-02-05 00:43:19,391] DEBUG: MainThread: Starting new HTTP connection (1): 127.0.0.1 [2017-02-05 00:43:19,393] DEBUG: MainThread: http://127.0.0.1:4045 "GET /api/tunnels HTTP/1.1" 200 36 [2017-02-05 00:43:19,394] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec. [2017-02-05 00:43:20,397] DEBUG: MainThread: Starting new HTTP connection (1): 127.0.0.1 [2017-02-05 00:43:20,399] DEBUG: MainThread: http://127.0.0.1:4045 "GET /api/tunnels HTTP/1.1" 200 36 [2017-02-05 00:43:20,400] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec. [2017-02-05 00:43:21,403] DEBUG: MainThread: Starting new HTTP connection (1): 127.0.0.1 [2017-02-05 00:43:21,404] DEBUG: MainThread: http://127.0.0.1:4045 "GET /api/tunnels HTTP/1.1" 200 36 [2017-02-05 00:43:21,405] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec. [2017-02-05 00:43:22,406] CRITICAL: MainThread: Error initializing webhook: Did not receive any HTTPS tunnel from ngrok API. [2017-02-05 00:43:22,407] INFO: MainThread: Shutting down. [2017-02-05 00:43:22,408] DEBUG: Worker-0: Stopped. [2017-02-05 00:43:22,408] DEBUG: Worker-1: Stopped. Traceback (most recent call last): File "/usr/local/src/onedrived-dev/onedrived/od_main.py", line 56, in init_webhook webhook_server = od_webhook.get_webhook_server(context) File "/usr/local/src/onedrived-dev/onedrived/od_webhook.py", line 27, in get_webhook_server return WebhookListener(wh_config, OneDriveWebhookHandler) File "/usr/local/src/onedrived-dev/onedrived/od_webhooks/ngrok_server.py", line 40, in init self._read_ngrok_tunnels() File "/usr/local/src/onedrived-dev/onedrived/od_webhooks/ngrok_server.py", line 100, in _read_ngrok_tunnels raise RuntimeError('Did not receive any HTTPS tunnel from ngrok API.') RuntimeError: Did not receive any HTTPS tunnel from ngrok API.

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/lib/python3.5/site-packages/daemonocle/daemon.py", line 367, in _run self.worker() File "/usr/local/src/onedrived-dev/onedrived/od_main.py", line 204, in main init_webhook() File "/usr/local/src/onedrived-dev/onedrived/od_main.py", line 59, in init_webhook raise SystemExit() SystemExit

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/bin/onedrived", line 11, in load_entry_point('onedrived', 'console_scripts', 'onedrived')() File "/usr/lib/python3.5/site-packages/click/core.py", line 722, in call return self.main(args, kwargs) File "/usr/lib/python3.5/site-packages/click/core.py", line 697, in main rv = self.invoke(ctx) File "/usr/lib/python3.5/site-packages/click/core.py", line 1066, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) File "/usr/lib/python3.5/site-packages/click/core.py", line 895, in invoke return ctx.invoke(self.callback, ctx.params) File "/usr/lib/python3.5/site-packages/click/core.py", line 535, in invoke return callback(args, **kwargs) File "/usr/lib/python3.5/site-packages/daemonocle/cli.py", line 56, in subcommand daemon.do_action(name) File "/usr/lib/python3.5/site-packages/daemonocle/daemon.py", line 573, in do_action func() File "/usr/lib/python3.5/site-packages/daemonocle/daemon.py", line 444, in start self._run() File "/usr/lib/python3.5/site-packages/daemonocle/daemon.py", line 376, in _run self._shutdown('Exiting with message: ' + str(ex.code), 1) File "/usr/lib/python3.5/site-packages/daemonocle/daemon.py", line 347, in _shutdown self._close_pidfile() File "/usr/lib/python3.5/site-packages/daemonocle/daemon.py", line 125, in _close_pidfile os.remove(self.pidfile) FileNotFoundError: [Errno 2] No such file or directory: '/home/bakerr/.config/onedrived/onedrived.pid' [2017-02-05 00:43:22,414] DEBUG: Dummy-1: Closing database "/home/bakerr/.config/onedrived/items_d3838f8ebe5535a6.sqlite3". [2017-02-05 00:43:22,464] DEBUG: Dummy-1: Close <_UnixSelectorEventLoop running=False closed=False debug=True>

^C All children are gone. Parent is exiting...

Running again with --debug usually results in it running OK and syncing.

[xybu]

The problem comes from ngrok. It's supposed to expose a HTTPS tunnel to onedrived very fast but it failed to do so within 3s from the log you provided. Also there seems to be 5 ngrok processes hanging already because the default inspection port is 4040 and the one in the log has increased it to 4045.

May I know which version of ngrok you are using? Also you can open the inspection link (e.g., http://127.0.0.1:4045 if ngrok is using port 4045 for inspection) and check the connection rate.

To figure out if it's just running slow you might increase the limit in https://github.com/xybu/onedrived-dev/blob/master/onedrived/od_webhooks/ngrok_server.py#L31 and see after how many tries onedrived obtains the channel.

[xybu]

By the way what do you mean by "mostly OK" in debug mode? Does this also occur to debug mode?

[vk5ztv]

I have seen it happen once in debug mode also. Even when it does successfully start there appears to be at least one ngrok timeout error before we successfully startup.

ngrok is version 2.1.18.

Yes - there are "stale" ngrok sessions left after onedrived has exited.

bakerr 14552 1 0 00:34 ? 00:00:52 ngrok http 44463 -bind-tls=true --config /home/bakerr/.config/onedrived/ngrok_conf.yaml bakerr 14969 1 0 00:39 ? 00:00:55 ngrok http 39649 -bind-tls=true --config /home/bakerr/.config/onedrived/ngrok_conf.yaml bakerr 15138 1 0 00:40 ? 00:00:54 ngrok http 38863 -bind-tls=true --config /home/bakerr/.config/onedrived/ngrok_conf.yaml bakerr 15194 1 0 00:41 ? 00:00:53 ngrok http 41931 -bind-tls=true --config /home/bakerr/.config/onedrived/ngrok_conf.yaml bakerr 15239 1 0 00:42 ? 00:00:54 ngrok http 39807 -bind-tls=true --config /home/bakerr/.config/onedrived/ngrok_conf.yaml

After killing all the stale ngrok sessions ('pkill ngrok') I then tried starting it up in daemon mode again while watching the log file with tail -f . This time it started up:

[2017-02-05 10:54:38,313] INFO: MainThread: Session for account d3838f8ebe5535a6 will expire in 3599 seconds. [2017-02-05 10:54:38,313] INFO: MainThread: Sweeping onedrived temporary files from local repositories. [2017-02-05 10:54:39,334] INFO: MainThread: Local ngrok API url: http://127.0.0.1:4040/api [2017-02-05 10:54:39,342] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec. [2017-02-05 10:54:40,349] INFO: Webhook: Local webhook server listening on port 45147. [2017-02-05 10:54:40,349] INFO: Webhook: Webhook server listening on https://a334e2a9.ngrok.io/BeJHOjvRa. [2017-02-05 10:54:40,350] INFO: MainThread: Scheduled sync task for Drive d3838f8ebe5535a6 of account d3838f8ebe5535a6. [2017-02-05 10:54:40,351] INFO: Worker-0: Deleted 0 dead records from database. [2017-02-05 10:54:40,351] INFO: MainThread: Updating webhook for Drive d3838f8ebe5535a6. [2017-02-05 10:54:41,204] INFO: MainThread: Webhook for Drive d3838f8ebe5535a6 updated. [2017-02-05 10:54:41,204] INFO: MainThread: Will use webhook to trigger sync events. [2017-02-05 10:54:45,951] INFO: Worker-0: Remote item "/Documents/Rodney's Notebook" is neither a file nor a directory. Skip it.

So far uploads from Linux seem to be syncing OK. I'll try in the reverse direction to make sure that's also working as expected...

So far so good, although a remote file with reportedly >200 files in it seems not to have finished syncing - it has only 200 files locally and I cannot see any activity for that folder. I'll need to confirm later just how many files are in the remote folder.

[vk5ztv]

Hmmm...confirmed there are 324 files in the remote folder, but no sync activity for that folder now. I do have a large file upload in progress - will wait until that's finished before investigating further. That's probably unrelated to this issue though so if I need to I'll start a new one (although there may be a new commit related to this - is this perhaps related to issue #23?).

[xybu]

Be a little patient. By default the program only uses 2 worker threads. You can use command inotifywait -cmr /Your/local/OneDrive/repo to monitor the file/dir accesses happening there.

[vk5ztv]

OK - thanks. Will monitor and update on progress later.

[vk5ztv]

Hmmm - raising another issue - it seems there is a 200-file limit on the local folder.

[ustc9300]

I got the same problem as vk5ztv's. Can anybody give a hand ?

[olegTarassov]

Having the same issue

onedrived start --debug
Starting onedrived ... OK [2017-06-28 13:57:35,539] INFO: MainThread: Starting new HTTPS connection (1): login.live.com [2017-06-28 13:57:35,924] DEBUG: MainThread: "POST /oauth20_token.srf HTTP/1.1" 200 1698 [2017-06-28 13:57:35,963] INFO: MainThread: Starting new HTTPS connection (1): api.onedrive.com [2017-06-28 13:57:36,117] DEBUG: MainThread: "GET /v1.0/drives HTTP/1.1" 200 369 [2017-06-28 13:57:36,126] DEBUG: MainThread: Refreshing repository session. [2017-06-28 13:57:36,127] INFO: MainThread: Starting new HTTPS connection (1): login.live.com [2017-06-28 13:57:36,263] DEBUG: MainThread: "POST /oauth20_token.srf HTTP/1.1" 200 1698 [2017-06-28 13:57:36,301] INFO: MainThread: Session for account e72ceb50812e5b6f will expire in 3599 seconds. [2017-06-28 13:57:36,301] DEBUG: MainThread: Will refresh session in 3479 seconds. [2017-06-28 13:57:36,307] INFO: MainThread: Sweeping onedrived temporary files from local repositories. [2017-06-28 13:57:36,324] DEBUG: Worker-0: Started. [2017-06-28 13:57:36,325] DEBUG: Worker-1: Started. [2017-06-28 13:57:37,339] INFO: MainThread: Local ngrok API url: http://127.0.0.1:4040/api [2017-06-28 13:57:37,347] INFO: MainThread: Starting new HTTP connection (1): 127.0.0.1 [2017-06-28 13:57:37,349] DEBUG: MainThread: "GET /api/tunnels HTTP/1.1" 200 36 [2017-06-28 13:57:37,350] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec. [2017-06-28 13:58:07,566] CRITICAL: MainThread: Error initializing webhook: Did not receive any HTTPS tunnel from ngrok API. [2017-06-28 13:58:07,567] INFO: MainThread: Shutting down. Code: Exiting with message: None.

using ngrok version 2.2.4

Any idea?

[lcgogo]

Meet the similar issue, need config ngrok manually?

root@WDMyCloud:/mnt/shares/Public# onedrived start --debug Starting od_main.py ... OK [2017-12-21 12:24:34,439] DEBUG: MainThread: Starting new HTTPS connection (1): api.onedrive.com [2017-12-21 12:24:35,589] DEBUG: MainThread: https://api.onedrive.com:443 "GET /v1.0/drives HTTP/1.1" 200 377 [2017-12-21 12:24:35,653] DEBUG: MainThread: Refreshing repository session. [2017-12-21 12:24:35,660] DEBUG: MainThread: Starting new HTTPS connection (1): login.live.com [2017-12-21 12:24:36,880] DEBUG: MainThread: https://login.live.com:443 "POST /oauth20_token.srf HTTP/1.1" 200 1655 [2017-12-21 12:24:36,936] INFO: MainThread: Session for account 69eab5d5c6ae0f3f will expire in 3599 seconds. [2017-12-21 12:24:36,937] DEBUG: MainThread: Will refresh session in 3479 seconds. [2017-12-21 12:24:37,042] INFO: MainThread: Sweeping onedrived temporary files from local repositories. [2017-12-21 12:24:37,146] DEBUG: Worker-0: Started. [2017-12-21 12:24:37,148] DEBUG: Worker-1: Started. [2017-12-21 12:24:38,240] INFO: MainThread: Local ngrok API url: http://127.0.0.1:4040/api [2017-12-21 12:24:38,309] DEBUG: MainThread: Starting new HTTP connection (1): 127.0.0.1 [2017-12-21 12:24:38,316] DEBUG: MainThread: http://127.0.0.1:4040 "GET /api/tunnels HTTP/1.1" 200 36 [2017-12-21 12:24:38,322] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec. [2017-12-21 12:24:39,334] DEBUG: MainThread: Starting new HTTP connection (1): 127.0.0.1 [2017-12-21 12:24:39,341] DEBUG: MainThread: http://127.0.0.1:4040 "GET /api/tunnels HTTP/1.1" 200 36 [2017-12-21 12:24:39,347] ERROR: MainThread: Error reading ngrok API: ngrok API did not return any tunnel.. Retry in 1sec.

[ygbae]

Have you added the Drive (OneDrive repository) and set up the local OneDrive directory after adding your OneDrive account?

$ onedrived-pref drive set

[derrix060]

How did you guys install the ngrok? If you see on my README you will see this

# install ngrok from own website (ngrok.com) and install in /usr/local/bin
# Don't install ngrok with sudo apt-get install ngrok-client, it does not install the 'good' ngrok!