acd_cli icon indicating copy to clipboard operation
acd_cli copied to clipboard

Published 20 hours ago • verified publisher icon yadayada

Stream gets interrupted.

Open christianreiss opened this issue 8 years ago • 2 comments

Hey folks,

I am using the master version of the git doing a local mount. I am not doing any fancy stuff (rsync); this use case is most of the time read-only via cifs (smbd) that shares err, large files, that are viewed in real time (TV Recordings, really). My tiny linux set top box records things on the local hdd, rclone-copies them onto Amazon Cloud and my raspberry pi 3 mounts said drive via acd_cli and shares the directory via smbd. There are no permission issues, but the stream gets cut off after a while, the log containts entries like these:

16-10-09 16:06:59.772 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1167167488, 14)
16-10-09 16:06:59.773 [DEBUG] [acdcli.acd_fuse] - s: 1167167488-1303117823; r: 1167167488-1167298559
16-10-09 16:06:59.787 [DEBUG] [acdcli.acd_fuse] - <- read 131072
16-10-09 16:06:59.934 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1167298560, 14)
16-10-09 16:06:59.936 [DEBUG] [acdcli.acd_fuse] - s: 1167298560-1303117823; r: 1167298560-1167429631
16-10-09 16:06:59.950 [DEBUG] [acdcli.acd_fuse] - <- read 131072
16-10-09 16:07:00.769 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (4096, 1167589376, 14)
16-10-09 16:07:00.770 [DEBUG] [acdcli.acd_fuse] - s: 1167429632-1303117823; r: 1167589376-1167593471
16-10-09 16:07:00.771 [DEBUG] [acdcli.acd_fuse] - s: 778305536-1048575999; r: 1167589376-1167593471
16-10-09 16:07:00.772 [DEBUG] [acdcli.acd_fuse] - s: 3889868800-3889897847; r: 1167589376-1167593471
16-10-09 16:07:00.773 [DEBUG] [acdcli.acd_fuse] - s: 3889283072-3889897847; r: 1167589376-1167593471
16-10-09 16:07:00.774 [DEBUG] [acdcli.acd_fuse] - s: 3501924352-3889897847; r: 1167589376-1167593471
16-10-09 16:07:00.775 [DEBUG] [acdcli.acd_fuse] - s: 3112972288-3637129215; r: 1167589376-1167593471
16-10-09 16:07:00.775 [DEBUG] [acdcli.acd_fuse] - s: 3112054784-3636211711; r: 1167589376-1167593471
16-10-09 16:07:00.776 [DEBUG] [acdcli.acd_fuse] - s: 3112841216-3636342783; r: 1167589376-1167593471
16-10-09 16:07:00.777 [DEBUG] [acdcli.acd_fuse] - s: 3111923712-3636203519; r: 1167589376-1167593471
16-10-09 16:07:00.778 [DEBUG] [acdcli.acd_fuse] - s: 2724241408-3247480831; r: 1167589376-1167593471
16-10-09 16:07:00.779 [DEBUG] [acdcli.acd_fuse] - s: 2723192832-3247214591; r: 1167589376-1167593471
16-10-09 16:07:00.780 [DEBUG] [acdcli.acd_fuse] - s: 2335252480-2858491903; r: 1167589376-1167593471
16-10-09 16:07:00.781 [DEBUG] [acdcli.acd_fuse] - s: 2334203904-2858225663; r: 1167589376-1167593471
16-10-09 16:07:00.781 [DEBUG] [acdcli.acd_fuse] - s: 1945214976-2469375999; r: 1167589376-1167593471
16-10-09 16:07:00.782 [DEBUG] [acdcli.acd_fuse] - s: 1946267648-2469502975; r: 1167589376-1167593471
16-10-09 16:07:00.783 [DEBUG] [acdcli.acd_fuse] - s: 1945088000-2469236735; r: 1167589376-1167593471
16-10-09 16:07:00.784 [DEBUG] [acdcli.acd_fuse] - s: 1557368832-2081263615; r: 1167589376-1167593471
16-10-09 16:07:00.785 [DEBUG] [acdcli.acd_fuse] - s: 1556975616-2081001471; r: 1167589376-1167593471
16-10-09 16:07:00.786 [DEBUG] [acdcli.acd_fuse] - s: 1556713472-2080243711; r: 1167589376-1167593471
16-10-09 16:07:00.787 [DEBUG] [acdcli.acd_fuse] - s: 1167986688-1691504639; r: 1167589376-1167593471
16-10-09 16:07:00.787 [DEBUG] [acdcli.acd_fuse] - s: 1167216640-1691254783; r: 1167589376-1167593471
16-10-09 16:07:00.788 [DEBUG] [acdcli.acd_fuse] - s: 779259904-1302265855; r: 1167589376-1167593471
16-10-09 16:07:00.789 [DEBUG] [acdcli.acd_fuse] - s: 388997120-913276927; r: 1167589376-1167593471
16-10-09 16:07:00.790 [DEBUG] [acdcli.acd_fuse] - s: 3889897848-3889897847; r: 1167589376-1167593471
16-10-09 16:07:00.791 [DEBUG] [acdcli.acd_fuse] - s: 524288000-524287999; r: 1167589376-1167593471
16-10-09 16:07:00.792 [DEBUG] [acdcli.api.content] - chunk o 1167589376 l 524288000
16-10-09 16:07:00.793 [DEBUG] [acdcli.api.backoff_req] - Retry 0, waiting -349.661238s
16-10-09 16:07:00.794 [INFO] [acdcli.api.backoff_req] - GET "https://content-eu.drive.amazonaws.com/cdproxy/nodes/oUuyYlPpRPKVeTwLVAqqQg/content"
16-10-09 16:07:00.801 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (59): content-eu.drive.amazonaws.com
16-10-09 16:07:04.510 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/oUuyYlPpRPKVeTwLVAqqQg/content HTTP/1.1" 206 524288000
16-10-09 16:07:04.512 [DEBUG] [acdcli.api.backoff_req] - x-amzn-RequestId: 550bab55-98b9-415a-a3a7-e377569fd8b2
16-10-09 16:07:04.513 [DEBUG] [acdcli.acd_fuse] - <- read 4096
16-10-09 16:07:04.515 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (32768, 1167593472, 14)
16-10-09 16:07:04.516 [DEBUG] [acdcli.acd_fuse] - s: 1167593472-1691877375; r: 1167593472-1167626239
16-10-09 16:07:04.579 [DEBUG] [acdcli.acd_fuse] - <- read 32768
16-10-09 16:07:04.582 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (65536, 1167626240, 14)
16-10-09 16:07:04.583 [DEBUG] [acdcli.acd_fuse] - s: 1167626240-1691877375; r: 1167626240-1167691775
16-10-09 16:07:04.655 [DEBUG] [acdcli.acd_fuse] - <- read 65536
16-10-09 16:07:04.656 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1167822848, 14)
16-10-09 16:07:04.657 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1167691776, 14)
16-10-09 16:07:04.657 [DEBUG] [acdcli.acd_fuse] - s: 1167691776-1691877375; r: 1167822848-1167953919
16-10-09 16:07:04.658 [DEBUG] [acdcli.acd_fuse] - s: 1167429632-1303117823; r: 1167822848-1167953919
16-10-09 16:07:04.659 [DEBUG] [acdcli.acd_fuse] - s: 778305536-1048575999; r: 1167822848-1167953919
16-10-09 16:07:04.660 [DEBUG] [acdcli.acd_fuse] - s: 3889868800-3889897847; r: 1167822848-1167953919
16-10-09 16:07:04.660 [DEBUG] [acdcli.acd_fuse] - s: 3889283072-3889897847; r: 1167822848-1167953919
16-10-09 16:07:04.661 [DEBUG] [acdcli.acd_fuse] - s: 3501924352-3889897847; r: 1167822848-1167953919
16-10-09 16:07:04.661 [DEBUG] [acdcli.acd_fuse] - s: 3112972288-3637129215; r: 1167822848-1167953919
16-10-09 16:07:04.662 [DEBUG] [acdcli.acd_fuse] - s: 3112054784-3636211711; r: 1167822848-1167953919
16-10-09 16:07:04.662 [DEBUG] [acdcli.acd_fuse] - s: 3112841216-3636342783; r: 1167822848-1167953919
16-10-09 16:07:04.663 [DEBUG] [acdcli.acd_fuse] - s: 3111923712-3636203519; r: 1167822848-1167953919
16-10-09 16:07:04.663 [DEBUG] [acdcli.acd_fuse] - s: 2724241408-3247480831; r: 1167822848-1167953919
16-10-09 16:07:04.664 [DEBUG] [acdcli.acd_fuse] - s: 2723192832-3247214591; r: 1167822848-1167953919
16-10-09 16:07:04.664 [DEBUG] [acdcli.acd_fuse] - s: 2335252480-2858491903; r: 1167822848-1167953919
16-10-09 16:07:04.665 [DEBUG] [acdcli.acd_fuse] - s: 2334203904-2858225663; r: 1167822848-1167953919
16-10-09 16:07:04.665 [DEBUG] [acdcli.acd_fuse] - s: 1945214976-2469375999; r: 1167822848-1167953919
16-10-09 16:07:04.666 [DEBUG] [acdcli.acd_fuse] - s: 1946267648-2469502975; r: 1167822848-1167953919
16-10-09 16:07:04.666 [DEBUG] [acdcli.acd_fuse] - s: 1945088000-2469236735; r: 1167822848-1167953919
16-10-09 16:07:04.667 [DEBUG] [acdcli.acd_fuse] - s: 1557368832-2081263615; r: 1167822848-1167953919
16-10-09 16:07:04.667 [DEBUG] [acdcli.acd_fuse] - s: 1556975616-2081001471; r: 1167822848-1167953919
16-10-09 16:07:04.668 [DEBUG] [acdcli.acd_fuse] - s: 1556713472-2080243711; r: 1167822848-1167953919
16-10-09 16:07:04.668 [DEBUG] [acdcli.acd_fuse] - s: 1167986688-1691504639; r: 1167822848-1167953919
16-10-09 16:07:04.669 [DEBUG] [acdcli.acd_fuse] - s: 1167216640-1691254783; r: 1167822848-1167953919
16-10-09 16:07:04.669 [DEBUG] [acdcli.acd_fuse] - s: 779259904-1302265855; r: 1167822848-1167953919
16-10-09 16:07:04.670 [DEBUG] [acdcli.acd_fuse] - s: 388997120-913276927; r: 1167822848-1167953919
16-10-09 16:07:04.670 [DEBUG] [acdcli.acd_fuse] - s: 3889897848-3889897847; r: 1167822848-1167953919
16-10-09 16:07:04.671 [DEBUG] [acdcli.acd_fuse] - s: 524288000-524287999; r: 1167822848-1167953919
16-10-09 16:07:04.671 [DEBUG] [acdcli.api.content] - chunk o 1167822848 l 524288000
16-10-09 16:07:04.672 [DEBUG] [acdcli.api.backoff_req] - Retry 0, waiting -0.139263s
16-10-09 16:07:04.673 [INFO] [acdcli.api.backoff_req] - GET "https://content-eu.drive.amazonaws.com/cdproxy/nodes/oUuyYlPpRPKVeTwLVAqqQg/content"
16-10-09 16:07:04.677 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (60): content-eu.drive.amazonaws.com
16-10-09 16:07:05.074 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/oUuyYlPpRPKVeTwLVAqqQg/content HTTP/1.1" 206 524288000
16-10-09 16:07:05.076 [DEBUG] [acdcli.api.backoff_req] - x-amzn-RequestId: dbe957be-37d5-4deb-91e9-2c6c9f53bec6
16-10-09 16:07:05.211 [DEBUG] [acdcli.acd_fuse] - <- read 131072
16-10-09 16:07:05.211 [DEBUG] [acdcli.acd_fuse] - s: 1167953920-1692110847; r: 1167691776-1167822847
16-10-09 16:07:05.212 [DEBUG] [acdcli.acd_fuse] - s: 1167691776-1691877375; r: 1167691776-1167822847
16-10-09 16:07:05.220 [DEBUG] [acdcli.acd_fuse] - <- read 131072
16-10-09 16:07:05.235 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1167953920, 14)
16-10-09 16:07:05.236 [DEBUG] [acdcli.acd_fuse] - s: 1167953920-1692110847; r: 1167953920-1168084991
16-10-09 16:07:05.246 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1168084992, 14)
16-10-09 16:07:05.284 [DEBUG] [acdcli.acd_fuse] - <- read 131072
16-10-09 16:07:05.285 [DEBUG] [acdcli.acd_fuse] - s: 1168084992-1692110847; r: 1168084992-1168216063
16-10-09 16:07:05.313 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1168216064, 14)
16-10-09 16:07:05.325 [DEBUG] [acdcli.acd_fuse] - <- read 131072
16-10-09 16:07:05.325 [DEBUG] [acdcli.acd_fuse] - s: 1168216064-1692110847; r: 1168216064-1168347135
16-10-09 16:07:05.354 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Computer/20161004_0131_-_N24_HD_-_ONLINE_DATING_-_DAS_GEFAEHRLICHE_SPIEL_MIT_DER_LIEBE.ts (131072, 1168347136, 14)
16-10-09 16:07:05.358 [DEBUG] [acdcli.acd_fuse] - <- read 131072

Full log is here: https://cloud.alpha-labs.net/index.php/s/Hn6UDEGqoVXkxoR

Things I have excluded as a source of trouble so far:

  • Internet Connection: Stable at 100mbit incoming; the stream uses ~10mbit max.
  • RPI3: The Load is way too tiny and does not spike.
  • Network Connection: Running cabled LAN.
  • Clients viewing the file (I have 4 at my disposal; none play it flawlessly).

Any pointers would be totally awesome! Thanks! <3

-Chris.

christianreiss avatar Oct 09 '16 16:10 christianreiss

Hey,

and once the connection/stream is gibberish, it does not pick up on speed (bandwith again).

Also this is happening:

16-10-09 18:15:35.942 [DEBUG] [acdcli.acd_fuse] - <- read 131072 16-10-09 18:15:35.944 [DEBUG] [acdcli.acd_fuse] - s: 146800640-146800639; r: 146800640-146931711 16-10-09 18:15:35.945 [DEBUG] [acdcli.acd_fuse] - s: 141557760-141557759; r: 146800640-146931711 16-10-09 18:15:35.946 [DEBUG] [acdcli.acd_fuse] - s: 136314880-136314879; r: 146800640-146931711 16-10-09 18:15:35.946 [DEBUG] [acdcli.acd_fuse] - s: 131072000-131071999; r: 146800640-146931711 [...] 16-10-09 18:15:35.979 [DEBUG] [acdcli.api.content] - chunk o 146800640 l 5242880 16-10-09 18:15:35.980 [DEBUG] [acdcli.api.backoff_req] - Retry 0, waiting -5.944577s 16-10-09 18:15:35.981 [DEBUG] [acdcli.acd_fuse] - -> read /Recordings/boxy.owl.alpha-labs.net/Frauentausch/20160908_2112_-_RTLII_HD_-_FRAUENTAUSCH.ts (131072, 146931712, 86) 16-10-09 18:15:35.982 [INFO] [acdcli.api.backoff_req] - GET "https://content-eu.drive.amazonaws.com/cdproxy/nodes/Q0eQLl0GT3KVfYHgbGoreQ/content" 16-10-09 18:15:36.063 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/Q0eQLl0GT3KVfYHgbGoreQ/content HTTP/1.1" 302 0 16-10-09 18:15:36.231 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /AZWG9EVAG1J0PRC2VTYGX9UVRVU77IOYYNCXNGF11OYHFVAU57?response-content-disposition=attachment%3B%20filename%3D%2220160908_2112_-_RTLII_HD_-_FRAUENTAUSCH.ts%22&response-content-type=application%2Foctet-stream&X-Amz-Security-Token=FQoDYXdzEDIaDMke3vnHH4Z8duvbWyK3A3Uk9IVqZnc%2FuwyQcTEzSsKLgmvokR8dntvc0QnDCeTTEpSibJTMdt3BlovrE7jbe3s9BfFOY%2Fma[...]u%2FpvwU%3D&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20161009T181536Z&X-Amz-SignedHeaders=host&X-Amz-Expires=300&X-Amz-Credential=ASIAJCPFN6CORA5VUK6A%2F20161009%2Feu-west-1%2Fs3%2Faws4_request&X-Amz-Signature=4cd8dec8761fe1b1b97640f002d8fd9f0f7e424d97171bb59d161025d867eb7e HTTP/1.1" 206 5242880 16-10-09 18:15:36.402 [DEBUG] [acdcli.acd_fuse] - <- read 131072 16-10-09 18:15:36.404 [DEBUG] [acdcli.acd_fuse] - s: 146931712-152043519; r: 146931712-147062783

I tied increasing the chunk sizes, decreasing them... help :/

-Chris.

christianreiss avatar Oct 09 '16 18:10 christianreiss

@christianreiss If the stream interrupted issues are happening over fuse, have a look at my PR #374 since I added retry logic to make borgbackup work.

bgemmill avatar Oct 16 '16 01:10 bgemmill