search

lbryio / lbry-sdk

The LBRY SDK for building decentralized, censorship resistant, monetized, digital content apps.
https://lbry.com
MIT License
7.19k stars 483 forks source link

Streaming bugs megaissue #2034

Closed tzarebczan closed 5 years ago

tzarebczan commented 5 years ago
## The Issue - [ ] BLOCKER: very slow and blocking file list - jack aware. - [ ] was seeing this once in a while on windows + lots of blobs. Victor aware. Probably not a blocker. ```Traceback (most recent call last): File "c:\users\thoma\documents\lbry\lbrynet\extras\cli.py", line 287, in main loop.run_until_complete(daemon.stop_event.wait()) File "C:\Users\thoma\AppData\Local\Programs\Python\Python37-32\lib\asyncio\base_events.py", line 571, in run_until_complete self.run_forever() File "C:\Users\thoma\AppData\Local\Programs\Python\Python37-32\lib\asyncio\base_events.py", line 539, in run_forever self._run_once() File "C:\Users\thoma\AppData\Local\Programs\Python\Python37-32\lib\asyncio\base_events.py", line 1739, in _run_once event_list = self._selector.select(timeout) File "C:\Users\thoma\AppData\Local\Programs\Python\Python37-32\lib\selectors.py", line 323, in select r, w, _ = self._select(self._readers, self._writers, [], timeout) File "C:\Users\thoma\AppData\Local\Programs\Python\Python37-32\lib\selectors.py", line 314, in _select r, w, x = select.select(r, w, w, timeout) ValueError: too many file descriptors in select() ``` - [x] for lex: log stream create/update parameters used in publish to log file (good to debugging other users' log files). - [x] error when updating claim without the stream in file list. ``` Traceback (most recent call last): File "c:\users\thoma\documents\lbry\lbrynet\extras\daemon\Daemon.py", line 540, in _process_rpc_call result = await result File "c:\users\thoma\documents\lbry\lbrynet\extras\daemon\Daemon.py", line 2176, in jsonrpc_publish return await self.jsonrpc_stream_update(claims[0].claim_id, replace=True, **kwargs) File "c:\users\thoma\documents\lbry\lbrynet\extras\daemon\Daemon.py", line 2505, in jsonrpc_stream_update await self.storage.save_content_claim(stream_hash, new_txo.id) File "c:\users\thoma\documents\lbry\lbrynet\extras\daemon\storage.py", line 775, in save_content_claim await self.db.run(self._save_content_claim, claim_outpoint, stream_hash) File "C:\Users\thoma\AppData\Local\Programs\Python\Python37-32\lib\concurrent\futures\thread.py", line 57, in run result = self.fn(*self.args, **self.kwargs) File "c:\users\thoma\documents\lbry\lbry-venv\lib\site-packages\torba\client\basedatabase.py", line 61, in __run_transaction result = fun(self.connection, *args, **kwargs) # type: ignore File "c:\users\thoma\documents\lbry\lbrynet\extras\daemon\storage.py", line 753, in _save_content_claim raise Exception("stream not found") Exception: stream not found ``` - [x] BLOCKER? incomplete files continue to retry (this is different from old behavior and probably should be handled in the connection manager). Had trouble shutting down the sdk. On restart, it would try to start/stop the file. Not sure if it actually tried to complete it, but it didn't look like it. Need to make sure that the file will retry on restart at least (old behavior) - [x] takes about 5 - 15 seconds on shutdown when a stream is running sometimes. Cannot reproduce reliably. - [x] use file size from claim metadata for range requests if it falls within the estimated range. - [x] BLOCKER: metadata/new file updates not reflected in file list. How did these tests pass? https://github.com/lbryio/lbry/commit/8f96b07559c0b855030c75f5762b1ca7357d58e9 - [x] don't resume pending streams that are already saved on startup (happens when the download was active on restart). - [x] BLOCKER?: [Save blobs off - mobile mode] some files like lbry://bitcoin-and-friends-episode-1 / lbry://weekly-crypto-recap-kraken-delists-bsv require the last blob to be downloaded before the stream starts, and the 2nd file even re-downloads the 1st blob twice. These files are web optimized, so this should not happen. This also happens all the time on Chrome, but not on firefox. The in-app player only does the first blob twice / last blob bug on certain files, about 40 / 50 percent of files sampled. This would result in a lower time to stream from the app perspective since it has to download additional data. Not sure if this is a bug or it's just how it works. **Some combination of the last blob downloaded + first blob redownloaded is happening on about half my sample from front page so far.** - [x] BLOCKER? head blobs only being announced on downloads - this is not good right? Also, we only announce sd blob on published files. https://github.com/lbryio/lbry/issues/2079 - [x] BLOCKER?: I think "stopping inactive download" is happening too soon - seeing this while still streaming a file. When it tries to get more blobs, it starts peer search again. ```2019-05-06 19:35:07,041 INFO lbrynet.stream.managed_stream:258: start downloader for stream (sd hash: 362b66435ee5f21a16338e7c997fd171250450ab6323858c0e43d633497d0711cd540ab7662f0db63c83f08d824c62de) 2019-05-06 19:35:07,058 INFO lbrynet.stream.downloader:90: searching for peers for stream 362b66435ee5f21a16338e7c997fd171250450ab6323858c0e43d633497d0711cd540ab7662f0db63c83f08d824c62de 2019-05-06 19:35:07,059 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream 362b66435ee5f21a16338e7c997fd171250450ab6323858c0e43d633497d0711cd540ab7662f0db63c83f08d824c62de 2019-05-06 19:35:07,066 INFO lbrynet.stream.managed_stream:300: stream file to browser for lbry://bitcoin-and-friends-episode-1#76114ce9385aa581ae91774f54b328f5d693d38b (sd hash 362b66...) 2019-05-06 19:35:35,405 INFO lbrynet.blob_exchange.client:129: downloaded ea68030d from 51.37.122.63:3333 2019-05-06 19:35:35,412 INFO lbrynet.stream.managed_stream:320: sent browser blob 1/40 2019-05-06 19:35:35,425 INFO lbrynet.stream.managed_stream:300: stream file to browser for lbry://bitcoin-and-friends-episode-1#76114ce9385aa581ae91774f54b328f5d693d38b (sd hash 362b66...) 2019-05-06 19:35:52,264 INFO lbrynet.blob_exchange.client:129: downloaded 81f118cd from 51.37.122.63:3333 2019-05-06 19:35:52,271 INFO lbrynet.stream.managed_stream:320: sent browser (final) blob 40/40 2019-05-06 19:35:54,070 INFO lbrynet.stream.managed_stream:454: stopping inactive download for lbry://bitcoin-and-friends-episode-1#76114ce9385aa581ae91774f54b328f5d693d38b (362b66...) ``` - [x] BLOCKER: completed status set to false if an already downloaded/completed file is re-streamed via get/stream endpoint. (save blobs/files true, may happen other modes too) - [x] BLOCKER: Don't delete paid file list items that time out on SDblob. They should be kept in the stream manager. Don't send key payment before download. - [x] get --save_file=true does not work if the stream is in progress already. file save does. They should be interchangeable. See below for example. - [x] BLOCKER FOR MOBILE: save files/blobs false (mobile mode) - calling get and then get --save_file=true does not save file. file save works. They should be interchangeable. If you restart the SDK twice, the status goes to completed= false - this should not happen. Same happens when save blobs = false, save file = true. ``` 2019-05-06 10:13:22,635 INFO lbrynet.stream.stream_manager:377: starting download for jiggytom 2019-05-06 10:13:22,635 INFO lbrynet.stream.managed_stream:258: start downloader for stream (sd hash: dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf) 2019-05-06 10:13:22,674 INFO lbrynet.stream.downloader:90: searching for peers for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-06 10:13:24,784 INFO lbrynet.blob_exchange.client:129: downloaded dda49b89 from 18.213.255.15:5567 2019-05-06 10:13:24,784 INFO lbrynet.stream.downloader:71: downloaded sd blob dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-06 10:13:24,788 INFO lbrynet.stream.downloader:80: loaded stream manifest dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-06 10:13:24,788 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-06 10:13:25,544 INFO lbrynet.blob_exchange.server:67: sent 76d50b67 (2097152 bytes) to 103.41.27.171:55224 2019-05-06 10:13:25,781 INFO lbrynet.stream.managed_stream:454: stopping inactive download for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (dda49b...) 2019-05-06 10:13:42,847 INFO lbrynet.blob_exchange.server:67: sent ace33543 (2097152 bytes) to 103.41.27.171:55224 2019-05-06 10:13:49,644 INFO lbrynet.stream.stream_manager:339: already have stream for jiggytom 2019-05-06 10:13:49,645 INFO lbrynet.stream.managed_stream:258: start downloader for stream (sd hash: dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf) 2019-05-06 10:13:49,648 INFO lbrynet.stream.downloader:90: searching for peers for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-06 10:13:49,648 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-06 10:13:50,648 INFO lbrynet.stream.managed_stream:454: stopping inactive download for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (dda49b...) ``` - [x] BLOCKER - see a download path / written bytes even though I deleted the file. This used to update right away. This is important for the app since it would try to stream from the file which doesn't exist. - [x] BLOCKER - save blobs/files on - if /get endpoint is used, the file removes itself but saves download path/written bytes. ``` 2019-05-03 00:12:36,190 WARNING lbrynet.stream.managed_stream:360: removing incomplete download c:\testing\lbry036\downloads\TQUS44N6e6moJzrHJc8lQ6OC.mp4 for dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf ``` - [x] BLOCKER: figure out why lbry://ABoyAndHisDog won't stream on Windows Chrome. Works on Lunix. Range bytes on Windows `Range: bytes=1138752993-` , Linux: `Range: bytes=1133477888-` and `Range: bytes=1138786304-`. This may affect other streams as well. - [x] BLOCKER: start a stream, then call get with --save_file does not work. Probably related to bug with the incomplete removal above. - [x] BLOCKER: fix logging : `save file for lbry://None#None` / `start downloader for lbry://None#None (sd hash a562b2...)` - [x] BLOCKER - - download path / written bytes go null for a saved / published file after restarting the SDK anytime save files is set to off. Both should be populated if the file was saved, even after restart. - [x] BLOCKER - calling get with save files/blobs true should download both blobs and files. It just searches for blobs but doesn't do anything. Should not need to pass --save_file (it works when you do). ``` 2019-05-03 13:09:59,668 INFO lbrynet.stream.stream_manager:385: starting download for what 2019-05-03 13:09:59,668 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://None#None (sd hash d51692...) 2019-05-03 13:09:59,669 INFO lbrynet.stream.downloader:90: searching for peers for stream d5169241150022f996fa7cd6a9a1c421937276a3275eb912790bd07ba7aec1fac5fd45431d226b8fb402691e79aeb24b 2019-05-03 13:10:00,728 INFO lbrynet.blob_exchange.client:128: downloaded d5169241 from 35.153.147.111:3333 2019-05-03 13:10:00,728 INFO lbrynet.stream.downloader:71: downloaded sd blob d5169241150022f996fa7cd6a9a1c421937276a3275eb912790bd07ba7aec1fac5fd45431d226b8fb402691e79aeb24b 2019-05-03 13:10:00,731 INFO lbrynet.stream.downloader:80: loaded stream manifest d5169241150022f996fa7cd6a9a1c421937276a3275eb912790bd07ba7aec1fac5fd45431d226b8fb402691e79aeb24b 2019-05-03 13:10:00,732 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream d5169241150022f996fa7cd6a9a1c421937276a3275eb912790bd07ba7aec1fac5fd45431d226b8fb402691e79aeb24b 2019-05-03 13:10:01,739 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://what#6769855a9aa43b67086f9ff3c1a5bacb5698a27a (d51692...) ``` - [x] BLOCKER: a file that was started with --save_file / file save, or in save_files true mode should resume on restart. Right now it goes into stopped mode. - [x] BLOCKER: save files off - a stream that's cut off with a sdk shutdown may restart on next startup. Doesn't happen all the time, only sometimes - can't reproduce reliably. - [x] BLOCKER: After save file bug is fixed (where it removes itself), ensure that completed = true stays true after restart (save files on). - [x] Save files/blobs on - after streaming entire file and then seeking, request to start file downloader/ search for peers are made again for the same stream hash - this shouldn't be the case since we have all blobs saved already, right? ``` 2019-05-03 13:44:31,220 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://seven#ed78bbac94763698f4dc46266f45a403e986b1e7 (sd hash a562b2...) 2019-05-03 13:44:31,220 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://seven#ed78bbac94763698f4dc46266f45a403e986b1e7 (sd hash a562b2...) 2019-05-03 13:44:31,221 INFO lbrynet.stream.downloader:90: searching for peers for stream a562b2c222b8a648335be3670867eb97de71d2445182712a540297376fc2a642d5c1c0b9e00c9b3198cce31ad06ecac5 2019-05-03 13:44:31,222 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream a562b2c222b8a648335be3670867eb97de71d2445182712a540297376fc2a642d5c1c0b9e00c9b3198cce31ad06ecac5 2019-05-03 13:44:31,244 INFO lbrynet.stream.managed_stream:326: sent browser blob 1/48 2019-05-03 13:44:31,253 INFO lbrynet.stream.managed_stream:326: sent browser blob 2/48 2019-05-03 13:44:31,261 INFO lbrynet.stream.managed_stream:326: sent browser blob 3/48 2019-05-03 13:44:31,474 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://seven#ed78bbac94763698f4dc46266f45a403e986b1e7 (sd hash a562b2...) 2019-05-03 13:44:31,483 INFO lbrynet.stream.managed_stream:326: sent browser blob 1/48 ``` - [x] ENSURE THIS DOES NOT HAPPEN AFTER BUGS ARE FIXED: stream locks up if you start streaming, then call file save, and then try to scrub towards end of file. Same thing would happen if get was called with save file and then someone tried to scrub while it was downloading. - [x] ENSURE THIS WORKS WHEN BUGS ARE FIXED: need to make sure analytics still work - [x] this happens often around the first blob of streams. ```2019-05-02 17:49:49,955 INFO lbrynet.stream.managed_stream:346: write blob 1/10 2019-05-02 17:49:49,964 WARNING lbrynet.blob_exchange.client:39: Protocol received data before expected, probable race on keep alive. Closing transport. Task exception was never retrieved future: exception=AttributeError("'NoneType' object has no attribute 'write'")> Traceback (most recent call last): File "c:\users\thoma\documents\lbry\lbrynet\blob_exchange\downloader.py", line 44, in request_blob_from_peer self.config.blob_download_timeout, connected_transport=transport File "c:\users\thoma\documents\lbry\lbrynet\blob_exchange\client.py", line 209, in request_blob return await protocol.download_blob(blob) File "c:\users\thoma\documents\lbry\lbrynet\blob_exchange\client.py", line 158, in download_blob return await self._download_blob() File "c:\users\thoma\documents\lbry\lbrynet\blob_exchange\client.py", line 95, in _download_blob self.transport.write(msg) AttributeError: 'NoneType' object has no attribute 'write' ``` - [ ] still getting these when stopping, also logged in 0.37 megaissue: ``` destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> ``` - [x] uncaught error when file not available: ``` 2019-04-18 17:15:05,673 INFO lbrynet.stream.stream_manager:384: starting download for lbry://game-of-thrones-s08e01 2019-04-18 17:15:05,696 INFO lbrynet.stream.downloader:90: searching for peers for stream 28bee621f4a04207e7e29567c2ad1c4974d198f9a8f86a74986df1977a4f476127cc70d531c65b4bff28a2aaf6d54404 2019-04-18 17:15:07,799 WARNING lbrynet.blob_exchange.client:100: 28bee621f4a04207e7e29567c2ad1c4974d198f9a8f86a74986df1977a4f476127cc70d531c65b4bff28a2aaf6d54404 not in availability response from 18.213.255.15:5567 2019-04-18 17:15:07,800 WARNING lbrynet.blob_exchange.client:101: {'blob_data_payment_rate': 'RATE_ACCEPTED', 'error': 'blob not found', 'lbrycrd_address': 'bJxKvpD96kaJLriqVajZ7SaQTsWWyrGQct'} 2019-04-18 17:15:17,989 WARNING lbrynet.blob_exchange.client:100: 28bee621f4a04207e7e29567c2ad1c4974d198f9a8f86a74986df1977a4f476127cc70d531c65b4bff28a2aaf6d54404 not in availability response from 18.213.255.15:5567 2019-04-18 17:15:17,990 WARNING lbrynet.blob_exchange.client:101: {'blob_data_payment_rate': 'RATE_ACCEPTED', 'error': 'blob not found', 'lbrycrd_address': 'bJxKvpD96kaJLriqVajZ7SaQTsWWyrGQct'} 2019-04-18 17:15:24,638 WARNING lbrynet.extras.daemon.Daemon:933: Error downloading lbry://game-of-thrones-s08e01: Task was destroyed but it is pending! task: wait_for=()]>> Exception ignored in: RuntimeError: coroutine ignored GeneratorExit Task was destroyed but it is pending! task: ._add_hashes_from_queue() running at lbrynet\dht\node.py:193> wait_for=()]>> Task was destroyed but it is pending! task: wait_for=()]>> Task exception was never retrieved future: ._aclose() done, defined at lbrynet\dht\protocol\async_generator_junction.py:75> exception=StopAsyncIteration()> Traceback (most recent call last): File "lbrynet\dht\protocol\async_generator_junction.py", line 82, in _aclose StopAsyncIteration ``` - [ ] (THIS SHOULD BE FIXED, WILL NEED TO CONFIRM ON MOBILE). fresh install on mobile of rc4 (save files/blobs off). something similar happens with some combination of stream + delete + restream. Other files work. Will need to try with victors branch. ``` 2019-04-30 12:33:50,454 INFO lbrynet.stream.stream_manager:391: starting download for lbry://initial-d-21-years-later-still-a-must#5508a6113050a8c306d98cab3cad86beec131ed0 2019-04-30 12:33:50,678 INFO lbrynet.stream.downloader:90: searching for peers for stream be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:50,814 INFO lbrynet.blob_exchange.client:125: downloaded be102200 from 18.213.255.15:5567 2019-04-30 12:33:50,815 INFO lbrynet.stream.downloader:71: downloaded sd blob be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:50,829 INFO lbrynet.stream.downloader:80: loaded stream manifest be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:50,830 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:50,854 WARNING lbrynet.extras.daemon.Daemon:934: Error downloading lbry://initial-d-21-years-later-still-a-must#5508a6113050a8c306d98cab3cad86beec131ed0: FOREIGN KEY constraint failed 2019-04-30 12:33:50,986 INFO lbrynet.stream.stream_manager:391: starting download for lbry://initial-d-21-years-later-still-a-must#5508a6113050a8c306d98cab3cad86beec131ed0 2019-04-30 12:33:50,987 INFO lbrynet.stream.downloader:90: searching for peers for stream be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:51,133 INFO lbrynet.blob_exchange.client:125: downloaded be102200 from 18.213.255.15:5567 2019-04-30 12:33:51,140 INFO lbrynet.stream.downloader:71: downloaded sd blob be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:51,154 INFO lbrynet.stream.downloader:80: loaded stream manifest be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:51,155 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-30 12:33:51,180 WARNING lbrynet.extras.daemon.Daemon:934: Error downloading lbry://initial-d-21-years-later-still-a-must#5508a6113050a8c306d98cab3cad86beec131ed0: FOREIGN KEY constraint failed 2019-04-30 12:33:52,388 INFO lbrynet.stream.stream_manager:391: starting download for lbry://initial-d-21-years-later-still-a-must#5508a6113050a8c306d98cab3cad86beec131ed0 ``` - [x] this is what I got with one stream at http://localhost:5279/get/one (save files on / save blobs off) - it logs duplicate sends to browser, and then a stopping inactive download right after. If I seek, it starts the stream again from scratch. File does save. Upon daemon restart in the mode, all files go back to stopped / completed = false. This is even though written bytes/path exists. ```2019-05-02 21:43:08,691 INFO lbrynet.stream.stream_manager:347: already have stream for lbry://one 2019-05-02 21:43:08,692 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (sd hash bea4d3...) 2019-05-02 21:43:08,724 INFO lbrynet.stream.downloader:90: searching for peers for stream bea4d30a1868a00e98297cfe8cdefc1be6c141b54bea3b7c95b34a66786c22ab4e9f35ae19aa453b3630e76afbd24fe2 2019-05-02 21:43:08,725 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream bea4d30a1868a00e98297cfe8cdefc1be6c141b54bea3b7c95b34a66786c22ab4e9f35ae19aa453b3630e76afbd24fe2 2019-05-02 21:43:08,734 INFO lbrynet.stream.managed_stream:339: save file for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (sd hash bea4d3...) -> c:\testing\lbry036\downloads\Jeremy Kauffman_3.mp4 2019-05-02 21:43:08,748 INFO lbrynet.stream.managed_stream:346: write blob 1/8 2019-05-02 21:43:08,757 INFO lbrynet.stream.managed_stream:346: write blob 2/8 2019-05-02 21:43:08,765 INFO lbrynet.stream.managed_stream:346: write blob 3/8 2019-05-02 21:43:08,775 INFO lbrynet.stream.managed_stream:346: write blob 4/8 2019-05-02 21:43:08,788 INFO lbrynet.stream.managed_stream:346: write blob 5/8 2019-05-02 21:43:08,797 INFO lbrynet.stream.managed_stream:346: write blob 6/8 2019-05-02 21:43:08,799 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (sd hash bea4d3...) 2019-05-02 21:43:08,806 INFO lbrynet.stream.managed_stream:346: write blob 7/8 2019-05-02 21:43:08,817 INFO lbrynet.stream.managed_stream:326: sent browser blob 1/8 2019-05-02 21:43:08,823 INFO lbrynet.stream.managed_stream:346: write blob 8/8 2019-05-02 21:43:08,838 INFO lbrynet.stream.managed_stream:326: sent browser blob 2/8 2019-05-02 21:43:08,847 INFO lbrynet.stream.managed_stream:326: sent browser blob 3/8 2019-05-02 21:43:09,141 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (sd hash bea4d3...) 2019-05-02 21:43:09,150 INFO lbrynet.stream.managed_stream:326: sent browser blob 1/8 2019-05-02 21:43:09,160 INFO lbrynet.stream.managed_stream:326: sent browser blob 2/8 2019-05-02 21:43:09,169 INFO lbrynet.stream.managed_stream:326: sent browser blob 3/8 2019-05-02 21:43:09,178 INFO lbrynet.stream.managed_stream:326: sent browser blob 4/8 2019-05-02 21:43:09,186 INFO lbrynet.stream.managed_stream:326: sent browser blob 5/8 2019-05-02 21:43:12,751 INFO lbrynet.stream.managed_stream:326: sent browser blob 6/8 2019-05-02 21:43:12,758 INFO lbrynet.stream.managed_stream:326: sent browser blob 7/8 2019-05-02 21:43:26,543 INFO lbrynet.stream.managed_stream:326: sent browser (final) blob 8/8 2019-05-02 21:43:27,733 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (bea4d3...) ``` - [x] save blobs on, save file off. It stops inactive download right away. When running get again with --save, it adds head blob to search -why? It times out again after download. Adds heads blob to search again when calling the range request url. ``` 019-05-02 23:59:35,134 INFO lbrynet.stream.downloader:80: loaded stream manifest dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-02 23:59:35,134 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-02 23:59:35,147 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-02 23:59:35,528 INFO lbrynet.blob_exchange.client:128: downloaded e6fd196d from 18.213.255.15:5567 2019-05-02 23:59:35,539 INFO lbrynet.stream.managed_stream:326: sent browser blob 1/7 2019-05-02 23:59:35,649 INFO lbrynet.blob_exchange.client:128: downloaded 8d28fc2d from 24.184.108.248:3336 2019-05-02 23:59:35,658 INFO lbrynet.stream.managed_stream:326: sent browser blob 2/7 2019-05-02 23:59:35,774 INFO lbrynet.blob_exchange.client:128: downloaded 4f267457 from 24.184.108.248:3336 2019-05-02 23:59:35,782 INFO lbrynet.stream.managed_stream:326: sent browser blob 3/7 2019-05-02 23:59:35,813 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-02 23:59:35,822 INFO lbrynet.stream.managed_stream:326: sent browser blob 1/7 2019-05-02 23:59:35,832 INFO lbrynet.stream.managed_stream:326: sent browser blob 2/7 2019-05-02 23:59:35,840 INFO lbrynet.stream.managed_stream:326: sent browser blob 3/7 2019-05-02 23:59:35,948 INFO lbrynet.blob_exchange.client:128: downloaded fbe7675f from 24.184.108.248:3336 2019-05-02 23:59:35,960 INFO lbrynet.stream.managed_stream:326: sent browser blob 4/7 2019-05-02 23:59:36,061 INFO lbrynet.blob_exchange.client:128: downloaded af984dea from 24.184.108.248:3336 2019-05-02 23:59:36,071 INFO lbrynet.stream.managed_stream:326: sent browser blob 5/7 2019-05-02 23:59:36,173 INFO lbrynet.blob_exchange.client:128: downloaded a778678b from 24.184.108.248:3336 2019-05-02 23:59:36,182 INFO lbrynet.stream.managed_stream:326: sent browser blob 6/7 2019-05-02 23:59:36,233 INFO lbrynet.blob_exchange.client:128: downloaded 486702c1 from 24.184.108.248:3336 2019-05-02 23:59:36,237 INFO lbrynet.stream.managed_stream:326: sent browser (final) blob 7/7 2019-05-02 23:59:38,148 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (dda49b...) 2019-05-02 23:59:47,906 INFO lbrynet.dht.blob_announcer:29: 1 blobs to announce 2019-05-02 23:59:50,677 INFO lbrynet.dht.protocol.routing_table:289: join buckets 1 2019-05-02 23:59:56,225 INFO lbrynet.dht.node:92: Stored e6fd196d to 8 of 8 attempted peers 2019-05-02 23:59:56,227 INFO lbrynet.dht.blob_announcer:45: announced 1 blobs 2019-05-03 00:00:12,959 INFO lbrynet.stream.stream_manager:347: already have stream for jiggytom 2019-05-03 00:00:12,960 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-03 00:00:12,961 INFO lbrynet.stream.downloader:90: searching for peers for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-03 00:00:12,961 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-03 00:00:12,968 INFO lbrynet.stream.managed_stream:339: save file for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) -> c:\testing\lbry036\downloads\TQUS44N6e6moJzrHJc8lQ6OC.mp4 2019-05-03 00:00:12,975 INFO lbrynet.stream.managed_stream:346: write blob 1/7 2019-05-03 00:00:12,982 INFO lbrynet.stream.managed_stream:346: write blob 2/7 2019-05-03 00:00:12,991 INFO lbrynet.stream.managed_stream:346: write blob 3/7 2019-05-03 00:00:13,000 INFO lbrynet.stream.managed_stream:346: write blob 4/7 2019-05-03 00:00:13,010 INFO lbrynet.stream.managed_stream:346: write blob 5/7 2019-05-03 00:00:13,019 INFO lbrynet.stream.managed_stream:346: write blob 6/7 2019-05-03 00:00:13,024 INFO lbrynet.stream.managed_stream:346: write blob 7/7 2019-05-03 00:00:14,982 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (dda49b...) 2019-05-03 00:01:08,665 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-03 00:01:08,666 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-03 00:01:08,668 INFO lbrynet.stream.downloader:90: searching for peers for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-03 00:01:08,668 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-03 00:01:08,681 INFO lbrynet.stream.managed_stream:326: sent browser blob 5/7 2019-05-03 00:01:08,691 INFO lbrynet.stream.managed_stream:326: sent browser blob 6/7 2019-05-03 00:01:08,710 INFO lbrynet.stream.managed_stream:326: sent browser (final) blob 7/7 2019-05-03 00:01:09,673 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (dda49b...) 2019-05-03 00:01:11,770 INFO torba.client.baseledger:133: lbc_mainnet: added BlockHeightEvent(height=561246, change=1) header blocks, final height 561246 2019-05-03 00:01:13,544 INFO lbrynet.stream.managed_stream:306: stream file to browser for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-03 00:01:13,544 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (sd hash dda49b...) 2019-05-03 00:01:13,546 INFO lbrynet.stream.downloader:90: searching for peers for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-03 00:01:13,546 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream dda49b896ccf4062b364faedddec586e06de50e2faa6a18ae2e83c405ee200ae05b587a20b5af7c343763b6dc9d86ddf 2019-05-03 00:01:13,559 INFO lbrynet.stream.managed_stream:326: sent browser blob 4/7 2019-05-03 00:01:13,569 INFO lbrynet.stream.managed_stream:326: sent browser blob 5/7 2019-05-03 00:01:13,575 INFO lbrynet.stream.managed_stream:326: sent browser blob 6/7 2019-05-03 00:01:14,558 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://jiggytom#2a4f9d71111b1d110ee42e8aa17e5c007022ab1c (dda49b...) ``` - [ ] on shutdown ``` 19-05-02 21:52:14,085 INFO lbrynet.dht.node:108: Stopped DHT node 2019-05-02 21:52:14,090 WARNING lbrynet.dht.protocol.protocol:432: error raised handling b'ping' request from 67.160.173.105:4444 - () Task exception was never retrieved future: exception=TransportNotConnected()> Traceback (most recent call last): File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 419, in handle_request_datagram await self.add_peer(peer) File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 370, in add_peer return await self._add_peer(peer) File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 357, in _add_peer await to_replace_rpc.ping() File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 136, in ping self.peer, RequestDatagram.make_ping(self.protocol.node_id) File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 521, in send_request await self._send(peer, request) File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 548, in _send raise TransportNotConnected() lbrynet.dht.error.TransportNotConnected During handling of the above exception, another exception occurred: Traceback (most recent call last): File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 436, in handle_request_datagram str(err).encode()) File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 543, in send_error await self._send(peer, error) File "c:\users\thoma\documents\lbry\lbrynet\dht\protocol\protocol.py", line 548, in _send raise TransportNotConnected() lbrynet.dht.error.TransportNotConnected 2019-05-02 21:52:14,099 INFO lbrynet.extras.daemon.exchange_rate_manager:217: Stopping exchange rate manager ``` - [x] sometimes streams just lock up and need to be deleted, not sure why yet. Seems to be reproducible sometimes on lbry://ABoyAndHisDog. This is a non-web optimized file that should start streaming if it gets the last few blobs. On latest version, it doesn't stream at all, and it used to sometimes before. Now it tries to stream 344/344 as opposed to 343 before. - [x] calling get with --save_file doesn't actually save the file - doesn't matter if it's already streaming or a new request (save_files off, save_blobs on). file_save works on an existing request. Should it work for new requests, or only when it's in file_list? - [x] WILL OPEN NEW ISSUE file commands should take a URL, so we can be consistent between get / file save on a URL. - [X] streams are not timing out after closing the get page. File list shows running. This is still happening on 0.37RC1. They do time out if you pause the stream. - [x] add logging when file is written to directory (i.e. on file save / get -save_file) - [X] blobs sent multiple times, or just a logging bug? Why is it trying to look at the last blob? lbry://initial-d-21-years-later-still-a-must ``` 2019-04-26 09:48:29,026 INFO lbrynet.stream.downloader:90: searching for peers for stream be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-26 09:48:29,026 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream be102200ad4e9297f69d87d607aa29ba383e5b59e44eccbcf46006621838876130292e74c57da15d7f958c90c4cf2e40 2019-04-26 09:48:29,051 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 1/38 2019-04-26 09:48:29,063 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 2/38 2019-04-26 09:48:29,077 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 3/38 2019-04-26 09:48:29,088 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 4/38 2019-04-26 09:48:29,387 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 1/38 2019-04-26 09:48:29,397 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 2/38 2019-04-26 09:48:29,406 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 3/38 2019-04-26 09:48:29,417 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 4/38 2019-04-26 09:48:29,428 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 5/38 2019-04-26 09:48:29,498 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 6/38 2019-04-26 09:48:29,836 INFO lbrynet.extras.daemon.Daemon:514: streamed blob 38/38 ``` - [x] resuming 2 downloads on restart? Didn't have any that failed, could have been something that was running before. Both have blobs written and stay in running mode even though the stream times out due to inactivity. Restart again on reboot. ``` 2019-04-27 19:31:22,144 INFO lbrynet.stream.stream_manager:183: resuming 2 downloads 2019-04-27 19:31:22,208 INFO lbrynet.stream.downloader:90: searching for peers for stream bea4d30a1868a00e98297cfe8cdefc1be6c141b54bea3b7c95b34a66786c22ab4e9f35ae19aa453b3630e76afbd24fe2 2019-04-27 19:31:22,209 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream bea4d30a1868a00e98297cfe8cdefc1be6c141b54bea3b7c95b34a66786c22ab4e9f35ae19aa453b3630e76afbd24fe2 2019-04-27 19:31:22,213 INFO lbrynet.stream.downloader:90: searching for peers for stream e899c6c528ea302e66582ec577eb98ed194aa536df451bd33bdd0c8ad078640ab3721f4764a149690a4d8c5cc7d77c54 2019-04-27 19:31:22,216 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream e899c6c528ea302e66582ec577eb98ed194aa536df451bd33bdd0c8ad078640ab3721f4764a149690a4d8c5cc7d77c54 ``` - [X] save files on / save blobs off - this downloads the entire file (all blobs) before streaming it. Sounds wrong. The latest version just did this one me...stopped writing after a few blobs and never played the file. Had to delete stream. ``` 2019-04-20 12:12:07,518 INFO lbrynet.stream.stream_manager:385: starting download for lbry://five 2019-04-20 12:12:07,518 INFO lbrynet.stream.downloader:90: searching for peers for stream 4b9311faf4b5796904d7e49026cf5bec35204022908463c4bfde093f15d117985ca70ccd53c17896b194ec6ac6f5e642 2019-04-20 12:12:09,680 INFO lbrynet.blob_exchange.client:125: downloaded 4b9311fa from 18.213.255.15:5567 2019-04-20 12:12:09,682 INFO lbrynet.stream.downloader:71: downloaded sd blob 4b9311faf4b5796904d7e49026cf5bec35204022908463c4bfde093f15d117985ca70ccd53c17896b194ec6ac6f5e642 2019-04-20 12:12:09,684 INFO lbrynet.stream.downloader:80: loaded stream manifest 4b9311faf4b5796904d7e49026cf5bec35204022908463c4bfde093f15d117985ca70ccd53c17896b194ec6ac6f5e642 2019-04-20 12:12:09,685 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream 4b9311faf4b5796904d7e49026cf5bec35204022908463c4bfde093f15d117985ca70ccd53c17896b194ec6ac6f5e642 2019-04-20 12:12:10,036 INFO lbrynet.blob_exchange.client:125: downloaded 320979c5 from 18.213.255.15:5567 2019-04-20 12:12:10,043 INFO lbrynet.stream.managed_stream:265: write blob 1/89 2019-04-20 12:12:10,253 INFO lbrynet.blob_exchange.client:125: downloaded 5e6bd697 from 18.213.255.15:5567 2019-04-20 12:12:10,261 INFO lbrynet.stream.managed_stream:265: write blob 2/89 2019-04-20 12:12:10,513 INFO lbrynet.blob_exchange.client:125: downloaded 320979c5 from 18.213.255.15:5567 2019-04-20 12:12:10,519 INFO lbrynet.extras.daemon.Daemon:513: streamed blob 1/89 2019-04-20 12:12:10,710 INFO lbrynet.blob_exchange.client:125: downloaded 16218a29 from 18.213.255.15:5567 2019-04-20 12:12:10,717 INFO lbrynet.stream.managed_stream:265: write blob 3/89 ``` - [X] concerning that all these streams timed out due to inactivity (been sitting here for a while) when I published/reflected something: ``` 2019-04-29 16:33:27,376 INFO lbrynet.stream.reflector.client:37: Finished sending reflector 9 blobs 2019-04-29 16:33:36,772 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream d55f5f0741a4388145ef313a280a1e1d9af5b6b5c6e867c6d74c4b8fbf70daf619964beedd72a96d5c7787e2ef65cde1 2019-04-29 16:33:38,467 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream 192a9eba36acbb8f3135cd5dfa21908a67a85af18b40e93d7ab794a9a902309abe540ca2cd42be5c4640dc76e62e988c 2019-04-29 16:33:38,503 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream 77945921db2357f29b716ee4f011ec0af32f84b1b9b19b35dcc20ca24a979f12b2ebdaba58166add2cb97e3f39807178 2019-04-29 16:33:38,537 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream 17198539cd94344ae77bc2e9d25b40f48a770d787a95489437d1bcce765d6b9278baee7349c6fe0a8739b545a7ca60fc 2019-04-29 16:33:38,701 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream 39091cd45e2b4ef7b1a2886054dbcef60b8200bef672f06a854aa8457f3767830f18e01590ce97448f48ed7c31f2fe3b 2019-04-29 16:33:38,754 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream e22721d4e8b6616b7306fa1978c0f02df9e6f675829177d69c6d0a6226167290b2a7da54f87936f4a07f6497d40ac6f2 2019-04-29 16:33:38,825 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream b3291493f2d53ca16d821bd5cb53747fedd5f139a7217a2f13a14b4a2a62a58a57e09fadeb46ddb0800f3eb7a0ed73ea 2019-04-29 16:33:39,043 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream 77c9202bd9cced7dc0f803207c6267a3183990efa67e193ed28b76917b6b6a0df5576a013be9c74080509ac3ff4f6c39 2019-04-29 16:33:39,164 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream dd22a1058f6c60fad0d3b9f0fee6c5c013c7c66a8a844088b8c17897e0e387eb31d6da585112365e36e083146b3f58c6 2019-04-29 16:33:40,830 INFO lbrynet.stream.managed_stream:240: Stopping inactive download for stream 7de6c7c4fdc7caead11ec82f05503e9a164edbadcab433f064ccfb83efff6dbd4184c5c4fbe80cedc1077ea95c990d75 ``` - [X] WILL OPEN NEW ISSUE if I have the downloaded file, I should be able to stream from it directly - [x] Allow running streaming server on separate interface from the default 5279. - [X] duplicate logging /sending when 2 clients are open. Scenario is this: play file, see blobs 1 2 3 sent. Pause. Open same file in new window. See blobs 1 2 3 1 2 3 sent. Jack was able to reproduce. - [X] Had save blobs off, streamed something, then turned save blobs on...it saved data blobs but not the sd blob. - [X] when stopping sometimes: ``` 2019-04-27 19:39:12,844 INFO lbrynet.extras.daemon.exchange_rate_manager:217: Stopping exchange rate manager Task exception was never retrieved future: exception=TypeError('stat: path should be string, bytes, os.PathLike or integer, not NoneType')> Traceback (most recent call last): File "lbrynet\stream\stream_manager.py", line 184, in resume File "lbrynet\stream\stream_manager.py", line 95, in start_stream File "lbrynet\stream\managed_stream.py", line 234, in setup File "genericpath.py", line 30, in isfile TypeError: stat: path should be string, bytes, os.PathLike or integer, not NoneType ``` - [X] cannot restream something if the file exists (and save files set to true) ``` 2019-04-18 23:19:27,500 INFO lbrynet.stream.downloader:71: downloaded sd blob 5fcdfd4834684f2b593a2c4f865ccb4cbfd201ac3ac1308a6ba53266ecc360668c9e426303d76fb77a4c8f65ca71b008 2019-04-18 23:19:27,502 INFO lbrynet.stream.downloader:80: loaded stream manifest 5fcdfd4834684f2b593a2c4f865ccb4cbfd201ac3ac1308a6ba53266ecc360668c9e426303d76fb77a4c8f65ca71b008 2019-04-18 23:19:27,502 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream 5fcdfd4834684f2b593a2c4f865ccb4cbfd201ac3ac1308a6ba53266ecc360668c9e426303d76fb77a4c8f65ca71b008 2019-04-18 23:19:27,510 WARNING lbrynet.extras.daemon.Daemon:933: Error downloading lbry://10-best-anime-of-spring-2019-ones-to#a5b70fa9eb07a366c67a1e44c51b40233dc3fe4e: FOREIGN KEY constraint failed ``` - [X] race happened downloading blob: ``` 019-04-29 11:39:51,770 INFO lbrynet.extras.daemon.Daemon:523: streamed blob 33/38 2019-04-29 11:39:51,837 ERROR lbrynet.blob_exchange.client:158: race happened downloading a0404c0c1712ae4c4d8279ab14749d638ebb2b1ba9db1b8a015426521a5e6af4388b6d40e205ac7fbb2f898685d90462 from 47.196.178.180:3333 Traceback (most recent call last): File "lbrynet\blob_exchange\client.py", line 153, in download_blob File "lbrynet\blob\blob_file.py", line 306, in get_blob_writer File "lbrynet\blob\blob_file.py", line 205, in get_blob_writer OSError: attempted to download blob twice from 47.196.178.180:3333 ``` - [X] should we just save all sdblobs, regardless if they are paid or not? - they are saved in the db - [X] on exit sometimes: ``` Traceback (most recent call last): File "lbrynet\extras\cli.py", line 325, in File "lbrynet\extras\cli.py", line 296, in main File "asyncio\base_events.py", line 560, in run_until_complete File "asyncio\base_events.py", line 528, in run_forever File "asyncio\base_events.py", line 1764, in _run_once File "asyncio\events.py", line 88, in _run File "lbrynet\dht\node.py", line 203, in stream_peer_search_junction GeneratorExit [28624] Failed to execute script cli ``` - [X] random errors during streaming/download. ``` 2019-04-18 18:03:49,199 INFO lbrynet.blob_exchange.client:125: downloaded eceb1bd7 from 18.213.255.15:5567 Exception in callback AbstractBlob.get_blob_writer..writer_finished_callback() at lbrynet\blob\blob_file.py:206 handle: .writer_finished_callback() at lbrynet\blob\blob_file.py:206> Traceback (most recent call last): File "asyncio\events.py", line 88, in _run File "lbrynet\blob\blob_file.py", line 216, in writer_finished_callback File "lbrynet\blob\blob_file.py", line 195, in save_verified_blob File "lbrynet\blob\blob_file.py", line 253, in _write_blob OSError: already have bytes for blob 2019-04-18 18:03:49,461 INFO lbrynet.blob_exchange.client:125: downloaded eceb1bd7 from 18.213.255.15:5567 Exception in callback AbstractBlob.get_blob_writer..writer_finished_callback() at lbrynet\blob\blob_file.py:206 handle: .writer_finished_callback() at lbrynet\blob\blob_file.py:206> Traceback (most recent call last): File "asyncio\events.py", line 88, in _run File "lbrynet\blob\blob_file.py", line 216, in writer_finished_callback File "lbrynet\blob\blob_file.py", line 195, in save_verified_blob File "lbrynet\blob\blob_file.py", line 253, in _write_blob OSError: already have bytes for blob ``` - [x] if scrubbing too quickly via click/hold method on progress bar, the stream will lock up and browser will return the below. Need to delete stream to play it again. This is with streaming only on/save blobs on/off. Victor was able to reproduce - [x] logging for uri being started is missing in stream mode. ``` http://xxxxxx:5279/stream/5fcdfd4834684f2b593a2c4f865ccb4cbfd201ac3ac1308a6ba53266ecc360668c9e426303d76fb77a4c8f65ca71b008 net::ERR_CONTENT_LENGTH_MISMATCH 206 (Partial Content) ``` - [x] shutdown takes longer than usual when stream is active. It does force shutdown n ow. - [X] on restart (save files off), the stream that was playing tries to resume. ```2019-05-02 23:57:13,858 INFO lbrynet.stream.stream_manager:169: resuming 1 downloads 2019-05-02 23:57:13,859 INFO lbrynet.stream.managed_stream:258: start downloader for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (sd hash bea4d3...) 2019-05-02 23:57:13,910 INFO lbrynet.stream.downloader:90: searching for peers for stream bea4d30a1868a00e98297cfe8cdefc1be6c141b54bea3b7c95b34a66786c22ab4e9f35ae19aa453b3630e76afbd24fe2 2019-05-02 23:57:13,910 INFO lbrynet.stream.downloader:97: added head blob to peer search for stream bea4d30a1868a00e98297cfe8cdefc1be6c141b54bea3b7c95b34a66786c22ab4e9f35ae19aa453b3630e76afbd24fe2 2019-05-02 23:57:14,908 INFO lbrynet.stream.managed_stream:458: stopping inactive download for lbry://one#3ae4ed38414e426c29c2bd6aeab7a6ac5da74a98 (bea4d3...) ``` - [x] written bytes shows null right after a file save. Subsequent file list has them correctly. - [x] errors when stopping ``` 019-04-18 20:32:33,015 INFO lbrynet.blob_exchange.server:125: Stopped blob server 2019-04-18 20:32:33,015 ERROR lbrynet.dht.protocol.protocol:619: Unexpected error while storing blob_hash Traceback (most recent call last): File "lbrynet\dht\protocol\protocol.py", line 606, in store_to_peer File "lbrynet\dht\protocol\protocol.py", line 154, in store File "lbrynet\dht\protocol\protocol.py", line 534, in send_request File "asyncio\locks.py", line 92, in __aenter__ File "asyncio\locks.py", line 192, in acquire concurrent.futures._base.CancelledError 2019-04-18 20:32:33,028 INFO lbrynet.dht.node:108: Stopped DHT node 2019-04-18 20:32:33,039 INFO lbrynet.extras.daemon.exchange_rate_manager:217: Stopping exchange rate manager Traceback (most recent call last): File "lbrynet\extras\cli.py", line 325, in File "lbrynet\extras\cli.py", line 296, in main File "asyncio\base_events.py", line 560, in run_until_complete File "asyncio\base_events.py", line 528, in run_forever File "asyncio\base_events.py", line 1728, in _run_once File "selectors.py", line 323, in select File "selectors.py", line 314, in _select OSError: [WinError 10038] An operation was attempted on something that is not a socket [47536] Failed to execute script cli Task exception was never retrieved future: exception=AssertionError('need to have a sd blob to send at this point')> Traceback (most recent call last): File "lbrynet\stream\stream_manager.py", line 195, in reflect_streams File "lbrynet\stream\managed_stream.py", line 331, in upload_to_reflector File "lbrynet\stream\reflector\client.py", line 67, in send_descriptor AssertionError: need to have a sd blob to send at this point ``` ## System Configuration
  • LBRY Daemon version:
  • LBRY App version:
  • LBRY Installation ID:
  • Operating system:

Anything Else

Screenshots

Internal Use

Acceptance Criteria

1. 2. 3.

Definition of Done

  • [ ] Tested against acceptance criteria
  • [ ] Tested against the assumptions of user story
  • [ ] The project builds without errors
  • [ ] Unit tests are written and passing
  • [ ] Tests on devices/browsers listed in the issue have passed
  • [ ] QA performed & issues resolved
  • [ ] Refactoring completed
  • [ ] Any configuration or build changes documented
  • [ ] Documentation updated
  • [ ] Peer Code Review performed
lyoshenka commented 5 years ago

jack and i filed separate bug issues for each of these. closing the :mega: issue