Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

下载到最后回调两次99%但是接下来的任何进度 #631

Closed
Jacksgong opened this issue Jun 26, 2017 · 50 comments
Closed

下载到最后回调两次99%但是接下来的任何进度 #631

Jacksgong opened this issue Jun 26, 2017 · 50 comments
Labels
Milestone

Comments

@Jacksgong
Copy link
Collaborator

Jacksgong commented Jun 26, 2017

@Gongcong @wanghaihui

多次返回的总进度相同这个是有可能的

因为回调是根据是否字节数有增加,而非整体的进度百分比,而具体配置体现在根据间隔/回调进度等配置进行回调

但是根据你们( @Gongcong @wanghaihui ) 的描述:

因为我们现在用的就是最新的1.5.7版本,这个问题的复现情况是这样的,下载完后,然后再清除APP缓存数据,然后再下载,会有几率复现,我们打了log,progress是100,但是最后会出现两次progress=99, 然后,完全进度就死在那了,没有任何回调

似乎是怀疑下载完成了,但是没有回调完成对吗?

如果是,可以告知下当遇到这种特征情况时(如你们所说在第二次progress=99时):

  1. FileDownloader.getStatus(id, path)返回的状态如何?
  2. 本地的FileDownloadUtils.getTempPath(task.getTargetFilePath())文件是否存在?
  3. 本地的 task.getTargetFilePath()文件是否存在。
  4. 留意Logcat中是否有crash日志,或者warn/error的日志

P.S. 按照现有代码逻辑是不可能出现下载完成但不回调完成的。只有可能下载进程Crash?或者error的回调,因此我比较倾向于是否是下载进程Crash或者是网络情况导致

@Jacksgong Jacksgong changed the title 下载到最后回调两次99%但是没有任何进度 下载到最后回调两次99%但是接下来的任何进度 Jun 26, 2017
@wanghaihui
Copy link

06-26 16:49:39.308 9479-10094/com.wodi.who D/FileDownloader.MessageSnapshotGate: ~~~callback 342569507 old[3] new[3] 1
06-26 16:49:39.308 9479-10094/com.wodi.who D/FileDownloader.FileDownloadMessenger: notify progress [email protected]@9107a09 7269206 7292524
06-26 16:49:39.308 9479-10094/com.wodi.who D/FileDownloader.MessageSnapshotGate: ~~~callback 342569507 old[3] new[3] 1
06-26 16:49:39.308 9479-10094/com.wodi.who D/FileDownloader.FileDownloadMessenger: notify progress [email protected]@9107a09 7269206 7292524

@wanghaihui
Copy link

@Jacksgong 这个抓的最后暂停的log

@wanghaihui
Copy link

就是没有下载完成,应该是一直在下载,但是也没有触发超时暂停

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 这些日志无法定位到问题。我这边无法复现,可否贴下更全的完整的日志,顺便在遇到问题时在日志中输出上面提到的那几个数据。

P.S. 如果是超时,返回的是error而非pause,一般的读写超时是15s,注意关注有没有crash或者是error输出。

@wanghaihui
Copy link

06-26 17:11:09.187 2040-2040/com.wodi.who D/FileDownload: progress:99
06-26 17:11:09.188 2040-2040/com.wodi.who D/FileDownload: status: 3
06-26 17:11:09.188 2040-2040/com.wodi.who D/FileDownload: targetFileTempPath: /storage/emulated/0/Android/data/com.wodi.who/files/cocos/wolf/cocos_update.zip.temp
06-26 17:11:09.188 2040-2040/com.wodi.who D/FileDownload: targetFile: /storage/emulated/0/Android/data/com.wodi.who/files/cocos/wolf/cocos_update.zip
06-26 17:11:09.189 2040-2040/com.wodi.who D/FileDownload: progress:99
06-26 17:11:09.189 2040-2040/com.wodi.who D/FileDownload: status: 3
06-26 17:11:09.189 2040-2040/com.wodi.who D/FileDownload: targetFileTempPath: /storage/emulated/0/Android/data/com.wodi.who/files/cocos/wolf/cocos_update.zip.temp
06-26 17:11:09.189 2040-2040/com.wodi.who D/FileDownload: targetFile: /storage/emulated/0/Android/data/com.wodi.who/files/cocos/wolf/cocos_update.zip

@wanghaihui
Copy link

@Jacksgong

@wanghaihui
Copy link

@Jacksgong 这是打的几个数据,我感觉是有一个下载一直没完成,卡在那了

@Jacksgong
Copy link
Collaborator Author

Jacksgong commented Jun 26, 2017

@wanghaihui 嗯,谢谢,不过这里要判断是否存在 File#exists,而非需要将路径打出来。


不过根据你读取的status是 3,说明内部应该是还在下载,不存在已经完成了,还没有回调完成。


这样吧,你通过FileDownloadLog.NEED_LOG=true,将FileDownloader内部日志打开,然后再复现下,最后将最后的尽可能多的日志贴出来。

需要注意的是一般的读写超时是15s左右,最后等待15s左右看看有没有超时的error回调。

@wanghaihui
Copy link

wanghaihui commented Jun 26, 2017

log.txt

@wanghaihui
Copy link

FileDownloader.setupOnApplicationOnCreate(this).connectionCreator(new FileDownloadUrlConnection
.Creator(new FileDownloadUrlConnection.Configuration()
.connectTimeout(15_000) // set connection timeout.
.readTimeout(15_000) // set read timeout.
.proxy(Proxy.NO_PROXY) // set proxy
));

@wanghaihui
Copy link

上面是配置

@wanghaihui
Copy link

最后等待15s左右看看有没有超时的error回调---这个没有回调error

@wanghaihui
Copy link

这个问题不是必现,但是复现概率在oppo r9s上挺高的

@Jacksgong
Copy link
Collaborator Author

Jacksgong commented Jun 26, 2017

@wanghaihui 可是我这边看不到所有下载服务(默认是再下载进程(:filedownloader)上)的所有日志诶。。。估计你是就贴了你主进程的日志。


我主要想看下载服务上面的日志,可否提供下xxx.xxx.xxx:filedownloader下载进程的日志吗?


P.S. 或者是你通过在filedownloader.properties中配置file.non-pre-allocation=true,然后再贴主进程的日志,这样就有下载服务上的日志了。

@wanghaihui
Copy link

FileDownloadLog.NEED_LOG = BuildConfig.DEBUG;
FileDownloader.setupOnApplicationOnCreate(this).connectionCreator(new FileDownloadUrlConnection
.Creator(new FileDownloadUrlConnection.Configuration()
.connectTimeout(15_000) // set connection timeout.
.readTimeout(15_000) // set read timeout.
.proxy(Proxy.NO_PROXY) // set proxy
));

我这样设置 可以吗?

@wanghaihui
Copy link

@Jacksgong

@wanghaihui
Copy link

wanghaihui commented Jun 26, 2017

06-26 17:45:55.499 15718-16147/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-219479975] index[1] range[1200314, 0) current offset(1200314)
06-26 17:45:55.502 15718-16154/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -219479975 request header {Range=[bytes=0-1200313]}
06-26 17:45:55.503 15718-16155/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -219479975 request header {Range=[bytes=1200314-]}
06-26 17:45:55.581 15718-16154/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[0] for -219479975, is connected range[0, 1200313) current offset[0] with code[206]
06-26 17:45:55.581 15718-16155/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[1] for -219479975, is connected range[1200314, 0) current offset[1200314] with code[206]
06-26 17:45:55.581 15718-16155/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(1): range [1200314, 0), seek to[1200314]
06-26 17:45:55.582 15718-16154/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(0): range [0, 1200313), seek to[0]
06-26 17:45:55.612 15718-16154/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-219479975] index[0] offset[66337], consume[19]
06-26 17:45:55.646 15718-16155/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-219479975] index[1] offset[1201714], consume[13]
06-26 17:45:56.000 15718-16154/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1200313)  2400629
06-26 17:45:56.383 15718-16155/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1200314, 0)  2400629
06-26 17:45:56.383 15718-16147/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-219479975] TRUE FALSE
06-26 17:45:56.383 15718-16147/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-219479975] TRUE FALSE
06-26 17:46:04.640 15718-15730/com.wodi.who:filedownloader D/FileDownloader.FileDownloadManager: request start the task with url(https://qiniustatic.wodidashi.com/cocos_update_ball_1.5.7.zip) path(/storage/emulated/0/Android/data/com.wodi.who/files/cocos//ball/cocos_update.zip) isDirectory(FALSE)
06-26 17:46:04.672 15718-16348/com.wodi.who:filedownloader D/FileDownloader.FileDownloadUtils: can't continue -385457779 file not suit, exists[FALSE], directory[FALSE]
06-26 17:46:04.674 15718-16348/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-]}
06-26 17:46:04.720 15718-16348/com.wodi.who:filedownloader D/FileDownloader.FileDownloadUtils: etag find "lrtseV51yF-_y-77s1-9f4Rz-JgY" for task(-385457779)
06-26 17:46:04.775 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: fetch data with multiple connection(count: [3]) for task[-385457779]
06-26 17:46:04.775 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[0] range[0, 1900615) current offset(0)
06-26 17:46:04.775 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[1] range[1900616, 3801231) current offset(1900616)
06-26 17:46:04.776 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[2] range[3801232, 0) current offset(3801232)
06-26 17:46:04.782 15718-16355/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-1900615]}
06-26 17:46:04.783 15718-16356/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=1900616-3801231]}
06-26 17:46:04.786 15718-16357/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=3801232-]}
06-26 17:46:04.827 15718-16355/com.wodi.who:filedownloader D/libc-netbsd: [getaddrinfo]:  hostname=qiniustatic.wodidashi.com; servname=(null);   app_uid=10455; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
06-26 17:46:04.828 15718-16355/com.wodi.who:filedownloader I/System.out: [socket] connection qiniustatic.wodidashi.com/123.125.7.217:443;LocalPort=37691(15000)
06-26 17:46:04.834 15718-16357/com.wodi.who:filedownloader D/libc-netbsd: [getaddrinfo]:  hostname=qiniustatic.wodidashi.com; servname=(null);   app_uid=10455; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
06-26 17:46:04.835 15718-16356/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[1] for -385457779, is connected range[1900616, 3801231) current offset[1900616] with code[206]
06-26 17:46:04.836 15718-16357/com.wodi.who:filedownloader I/System.out: [socket] connection qiniustatic.wodidashi.com/123.125.7.235:443;LocalPort=59862(15000)
06-26 17:46:04.836 15718-16356/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(1): range [1900616, 3801231), seek to[1900616]
06-26 17:46:04.857 15718-16356/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[1] offset[1902016], consume[18]
06-26 17:46:05.076 15718-16357/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[2] for -385457779, is connected range[3801232, 0) current offset[3801232] with code[206]
06-26 17:46:05.077 15718-16357/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(2): range [3801232, 0), seek to[3801232]
06-26 17:46:05.118 15718-16357/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[2] offset[3802632], consume[41]
06-26 17:46:05.136 15718-16355/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[0] for -385457779, is connected range[0, 1900615) current offset[0] with code[206]
06-26 17:46:05.136 15718-16355/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(0): range [0, 1900615), seek to[0]
06-26 17:46:05.302 15718-16355/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[0] offset[65942], consume[39]
06-26 17:46:05.852 15718-16356/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1900616, 3801231)  5701850
06-26 17:46:05.852 15718-16357/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(2): [3801232, 0)  5701850
06-26 17:46:05.852 15718-16355/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1900615)  5701850
06-26 17:46:05.854 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
06-26 17:46:05.855 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
06-26 17:46:05.855 15718-16348/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
06-26 17:46:11.075 15718-15805/com.wodi.who:filedownloader I/System.out: [socket][:56735] exception
06-26 17:47:39.230 15718-15754/com.wodi.who:filedownloader I/TDLOG: postData()#Send data to server.
06-26 17:47:39.243 15718-15754/com.wodi.who:filedownloader D/libc-netbsd: [getaddrinfo]:  hostname=xdrig.com; servname=(null);   app_uid=10455; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
06-26 17:47:39.249 15718-15754/com.wodi.who:filedownloader I/System.out: [socket] connection /54.223.62.189:443;LocalPort=52130(60000)
06-26 17:47:39.487 15718-15754/com.wodi.who:filedownloader I/TDLOG: Send()# success : true

@wanghaihui
Copy link

这是filedownloader进程log

@Jacksgong
Copy link
Collaborator Author

Jacksgong commented Jun 26, 2017

@wanghaihui 谢谢,我们针对最后一次的任务来定位:

D/FileDownloader.FileDownloadManager: request start the task with url(https://qiniustatic.wodidashi.com/cocos_update_ball_1.5.7.zip) path(/storage/emulated/0/Android/data/com.wodi.who/files/cocos//ball/cocos_update.zip) isDirectory(FALSE)
D/FileDownloader.FileDownloadUtils: can't continue -385457779 file not suit, exists[FALSE], directory[FALSE]
D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-]}
D/FileDownloader.FileDownloadUtils: etag find "lrtseV51yF-_y-77s1-9f4Rz-JgY" for task(-385457779)
D/FileDownloader.DownloadLaunchRunnable: fetch data with multiple connection(count: [3]) for task[-385457779]
D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[0] range[0, 1900615) current offset(0)
D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[1] range[1900616, 3801231) current offset(1900616)
D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[2] range[3801232, 0) current offset(3801232)
D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-1900615]}
D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=1900616-3801231]}
D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=3801232-]}
D/libc-netbsd: [getaddrinfo]:  hostname=qiniustatic.wodidashi.com; servname=(null);   app_uid=10455; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
I/System.out: [socket] connection qiniustatic.wodidashi.com/123.125.7.217:443;LocalPort=37691(15000)
D/libc-netbsd: [getaddrinfo]:  hostname=qiniustatic.wodidashi.com; servname=(null);   app_uid=10455; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
D/FileDownloader.DownloadRunnable: the connection[1] for -385457779, is connected range[1900616, 3801231) current offset[1900616] with code[206]
I/System.out: [socket] connection qiniustatic.wodidashi.com/123.125.7.235:443;LocalPort=59862(15000)
D/FileDownloader.FetchDataTask: start fetch(1): range [1900616, 3801231), seek to[1900616]
D/FileDownloader.FetchDataTask: require sync id[-385457779] index[1] offset[1902016], consume[18]
D/FileDownloader.DownloadRunnable: the connection[2] for -385457779, is connected range[3801232, 0) current offset[3801232] with code[206]
D/FileDownloader.FetchDataTask: start fetch(2): range [3801232, 0), seek to[3801232]
D/FileDownloader.FetchDataTask: require sync id[-385457779] index[2] offset[3802632], consume[41]
D/FileDownloader.DownloadRunnable: the connection[0] for -385457779, is connected range[0, 1900615) current offset[0] with code[206]
D/FileDownloader.FetchDataTask: start fetch(0): range [0, 1900615), seek to[0]
D/FileDownloader.FetchDataTask: require sync id[-385457779] index[0] offset[65942], consume[39]
D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1900616, 3801231)  5701850
D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(2): [3801232, 0)  5701850
D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1900615)  5701850
D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE

如日志,最后一次任务是:

启动了三个连接线程下载:

D/FileDownloader.DownloadLaunchRunnable: fetch data with multiple connection(count: [3]) for task[-385457779]
D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[0] range[0, 1900615) current offset(0)
D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[1] range[1900616, 3801231) current offset(1900616)
D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[2] range[3801232, 0) current offset(3801232)

成功启动了对应的三个连接:

D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-1900615]}
D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=1900616-3801231]}
D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=3801232-]}

最终三个连接线程都下载完成:

D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1900616, 3801231)  5701850
D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(2): [3801232, 0)  5701850
D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1900615)  5701850
D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE

整个流程都是正确的,并且最后也完成了下载。这个任务最后你没有收到completed的回调吗?

@wanghaihui
Copy link

如果按这个分析的话,的确是正确的,但是我遇到的就是最后没调用completed,我再测试下

@wanghaihui
Copy link

06-26 19:49:11.531 16991-17006/com.wodi.who:filedownloader D/FileDownloader.FileDownloadManager: request start the task with url(https://qiniustatic.wodidashi.com/cocos_update_melee_1.5.6.zip) path(/storage/emulated/0/Android/data/com.wodi.who/files/cocos//melee/cocos_update.zip) isDirectory(FALSE)
06-26 19:49:11.557 16991-17604/com.wodi.who:filedownloader D/FileDownloader.FileDownloadUtils: can't continue -219479975 file not suit, exists[FALSE], directory[FALSE]
06-26 19:49:11.562 16991-17604/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -219479975 request header {Range=[bytes=0-]}
06-26 19:49:11.585 16991-17604/com.wodi.who:filedownloader D/FileDownloader.FileDownloadUtils: etag find "FrLW872xouYVFyChLKO7TI06lLUm" for task(-219479975)
06-26 19:49:11.635 16991-17604/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: fetch data with multiple connection(count: [2]) for task[-219479975]
06-26 19:49:11.635 16991-17604/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-219479975] index[0] range[0, 1200313) current offset(0)
06-26 19:49:11.635 16991-17604/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-219479975] index[1] range[1200314, 0) current offset(1200314)
06-26 19:49:11.637 16991-17608/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -219479975 request header {Range=[bytes=1200314-]}
06-26 19:49:11.637 16991-17607/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -219479975 request header {Range=[bytes=0-1200313]}
06-26 19:49:11.662 16991-17607/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[0] for -219479975, is connected range[0, 1200313) current offset[0] with code[206]
06-26 19:49:11.663 16991-17607/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(0): range [0, 1200313), seek to[0]
06-26 19:49:11.663 16991-17608/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[1] for -219479975, is connected range[1200314, 0) current offset[1200314] with code[206]
06-26 19:49:11.664 16991-17608/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(1): range [1200314, 0), seek to[1200314]
06-26 19:49:11.676 16991-17608/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-219479975] index[1] offset[1201714], consume[11]
06-26 19:49:11.722 16991-17607/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-219479975] index[0] offset[65937], consume[18]
06-26 19:49:12.392 16991-17608/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1200314, 0) 2400629
06-26 19:49:12.392 16991-17607/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1200313) 2400629
06-26 19:49:12.392 16991-17604/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-219479975] TRUE FALSE
06-26 19:49:12.393 16991-17604/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-219479975] TRUE FALSE

@wanghaihui
Copy link

这个是fileDownloader进程的log

@wanghaihui
Copy link

看起来好像是下载完成,但是的确
06-26 19:49:12.352 16562-17605/com.wodi.who D/FileDownloader.MessageSnapshotGate: ~~~callback -219479975 old[3] new[3] 1
06-26 19:49:12.352 16562-17605/com.wodi.who D/FileDownloader.FileDownloadMessenger: notify progress [email protected]@d7886e0 2390164 2400629

之后就没有调用completed

@wanghaihui
Copy link

// 执行下载过程
downloadId = FileDownloader.getImpl().create(downloadUrl)
.setPath(downloadPath, false)
.setListener(new FileDownloadSampleListener() {
@OverRide
protected void pending(BaseDownloadTask task, int soFarBytes, int totalBytes) {
super.pending(task, soFarBytes, totalBytes);
Timber.d("pending");
}

                                @Override
                                protected void connected(BaseDownloadTask task, String etag, boolean isContinue,
                                                         int soFarBytes, int totalBytes) {
                                    super.connected(task, etag, isContinue, soFarBytes, totalBytes);
                                    Timber.d("connected");
                                }

                                @Override
                                protected void progress(BaseDownloadTask task, int soFarBytes, int totalBytes) {
                                    super.progress(task, soFarBytes, totalBytes);
                                    final int dl_progress = (int) (soFarBytes * 100L) / totalBytes;
                                    Timber.d("progress:" + dl_progress);
                                    ((Activity) context).runOnUiThread(new Runnable() {
                                        @Override
                                        public void run() {
                                            if (newFragment.getDownloadProgressBar() != null) {
                                                newFragment.getDownloadProgressBar().setProgress(dl_progress);
                                            }
                                        }
                                    });
                                }

                                @Override
                                protected void blockComplete(BaseDownloadTask task) {
                                    super.blockComplete(task);
                                    Timber.d("blockComplete");
                                }

                                @Override
                                protected void retry(final BaseDownloadTask task, final Throwable ex,
                                                     final int retryingTimes, final int soFarBytes) {
                                    super.retry(task, ex, retryingTimes, soFarBytes);
                                    Timber.d("retry");
                                }

                                @Override
                                protected void completed(BaseDownloadTask task) {
                                    super.completed(task);
                                    Timber.d("completed");
                                    ((Activity) context).runOnUiThread(new Runnable() {
                                        @Override
                                        public void run() {
                                            if (newFragment.getDownloadProgressBar() != null) {
                                                newFragment.getDownloadProgressBar().setProgress(100);
                                            }
                                        }
                                    });

                                    //// TODO: 2017/6/26 remove unzip to blockComplete
                                    // 同时, 对下载成功的文件进行解压
                                    Observable.create(new Observable.OnSubscribe<String>() {
                                        @Override
                                        public void call(Subscriber<? super String> subscriber) {
                                            try {
                                                Timber.d("unzip begin");
                                                unZipCocos(BaseConfig.COCOS_FILE_DIR +
                                                        (TextUtils.isEmpty(newGamePath) ? "" : File.separator + newGamePath), passWord + "_xiangbudao", params);
                                                Timber.d("unzip done");
                                            } catch (ZipException e) {
                                                e.printStackTrace();
                                            } finally {
                                                DialogFragment prev = (DialogFragment) ((BaseActivity) context).getSupportFragmentManager().findFragmentByTag(DOWNLOAD_DIALOG_TAG);
                                                if (prev != null) {
                                                    prev.dismissAllowingStateLoss();
                                                }
                                            }
                                        }
                                    })
                                            .subscribeOn(Schedulers.io())
                                            .subscribe(new Subscriber<String>() {
                                                @Override
                                                public void onCompleted() {

                                                }

                                                @Override
                                                public void onError(Throwable e) {

                                                }

                                                @Override
                                                public void onNext(String s) {

                                                }
                                            });
                                }

                                @Override
                                protected void paused(BaseDownloadTask task, int soFarBytes, int totalBytes) {
                                    super.paused(task, soFarBytes, totalBytes);
                                    Timber.d("paused");
                                }

                                @Override
                                protected void error(BaseDownloadTask task, Throwable e) {
                                    super.error(task, e);
                                    Timber.d("error");
                                    e.printStackTrace();

                                    ((Activity) context).runOnUiThread(new Runnable() {
                                        @Override
                                        public void run() {
                                            DialogFragment prev = (DialogFragment) ((BaseActivity) context).getSupportFragmentManager().findFragmentByTag(DOWNLOAD_DIALOG_TAG);
                                            if (prev != null) {
                                                prev.dismissAllowingStateLoss();
                                            }

                                            Toast.makeText(context, context.getResources().
                                                    getString(R.string.str_please_retry), Toast.LENGTH_SHORT).show();
                                        }
                                    });
                                }

                                @Override
                                protected void warn(BaseDownloadTask task) {
                                    super.warn(task);
                                    Timber.d("error");
                                }
                            }).start();

@wanghaihui
Copy link

@Jacksgong 上面是下载的过程

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 谢谢,我看了你的代码这个是一个正常的使用场景,我在demo project中测试,始终无法复现。所以还需要你的协助:

  1. 你可否在filedownloader.properties中配置file.non-pre-allocation=true
  2. 然后再贴日志给我,这样我可以将下载服务的日志与非下载服务的日志联系起来一起看

@wanghaihui
Copy link

06-27 12:38:55.774 26393-26404/com.wodi.who:filedownloader D/FileDownloader.FileDownloadManager: request start the task with url(https://qiniustatic.wodidashi.com/cocos_update_ball_1.5.7.zip) path(/storage/emulated/0/Android/data/com.wodi.who/files/cocos//ball/cocos_update.zip) isDirectory(FALSE)
06-27 12:38:55.813 26393-27083/com.wodi.who:filedownloader D/FileDownloader.FileDownloadUtils: can't continue -385457779 file not suit, exists[FALSE], directory[FALSE]
06-27 12:38:55.815 26393-27083/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-]}
06-27 12:38:55.871 26393-27083/com.wodi.who:filedownloader D/FileDownloader.FileDownloadUtils: etag find "lrtseV51yF-_y-77s1-9f4Rz-JgY" for task(-385457779)
06-27 12:38:55.996 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: fetch data with multiple connection(count: [3]) for task[-385457779]
06-27 12:38:55.997 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[0] range[0, 1900615) current offset(0)
06-27 12:38:55.998 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[1] range[1900616, 3801231) current offset(1900616)
06-27 12:38:55.998 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: enable multiple connection: id[-385457779] index[2] range[3801232, 0) current offset(3801232)
06-27 12:38:56.003 26393-27089/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=1900616-3801231]}
06-27 12:38:56.003 26393-27090/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=3801232-]}
06-27 12:38:56.003 26393-27088/com.wodi.who:filedownloader D/FileDownloader.ConnectTask: -385457779 request header {Range=[bytes=0-1900615]}
06-27 12:38:56.078 26393-27090/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[2] for -385457779, is connected range[3801232, 0) current offset[3801232] with code[206]
06-27 12:38:56.079 26393-27090/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(2): range [3801232, 0), seek to[3801232]
06-27 12:38:56.090 26393-27090/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[2] offset[3802632], consume[10]
06-27 12:38:56.105 26393-27088/com.wodi.who:filedownloader D/libc-netbsd: [getaddrinfo]: hostname=qiniustatic.wodidashi.com; servname=(null); app_uid=10463; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
06-27 12:38:56.106 26393-27089/com.wodi.who:filedownloader D/libc-netbsd: [getaddrinfo]: hostname=qiniustatic.wodidashi.com; servname=(null); app_uid=10463; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
06-27 12:38:56.106 26393-27088/com.wodi.who:filedownloader I/System.out: [socket] connection qiniustatic.wodidashi.com/124.193.235.243:443;LocalPort=32780(15000)
06-27 12:38:56.116 26393-27089/com.wodi.who:filedownloader I/System.out: [socket] connection qiniustatic.wodidashi.com/124.193.235.243:443;LocalPort=42821(15000)
06-27 12:38:56.572 26393-26425/com.wodi.who:filedownloader I/TDLOG: postData()#Send data to server.
06-27 12:38:56.577 26393-26425/com.wodi.who:filedownloader D/libc-netbsd: [getaddrinfo]: hostname=xdrig.com; servname=(null); app_uid=10463; ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0 from prox result 0
06-27 12:38:56.580 26393-26425/com.wodi.who:filedownloader I/System.out: [socket] connection /52.80.17.81:443;LocalPort=45315(60000)
06-27 12:38:56.751 26393-27088/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[0] for -385457779, is connected range[0, 1900615) current offset[0] with code[206]
06-27 12:38:56.752 26393-27088/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(0): range [0, 1900615), seek to[0]
06-27 12:38:56.810 26393-27089/com.wodi.who:filedownloader D/FileDownloader.DownloadRunnable: the connection[1] for -385457779, is connected range[1900616, 3801231) current offset[1900616] with code[206]
06-27 12:38:56.811 26393-27089/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: start fetch(1): range [1900616, 3801231), seek to[1900616]
06-27 12:38:56.846 26393-27089/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[1] offset[1902016], consume[35]
06-27 12:38:57.204 26393-27088/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[0] offset[66904], consume[35]
06-27 12:38:57.365 26393-26425/com.wodi.who:filedownloader I/TDLOG: Send()# success : true
06-27 12:38:57.828 26393-27090/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(2): [3801232, 0) 5701850
06-27 12:38:58.458 26393-26478/com.wodi.who:filedownloader I/System.out: [socket][:41272] exception
06-27 12:38:58.701 26393-27088/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1900615) 5701850
06-27 12:38:58.701 26393-27089/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1900616, 3801231) 5701850
06-27 12:38:58.701 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
06-27 12:38:58.701 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
06-27 12:38:58.701 26393-27083/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE

@Jacksgong 我按你的方式配了,不过貌似log没什么变化

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 你确定你是在assets/filedownloader.properties中配置了吗?(可以留意下 FileDownloadProperties tag的logcat输出,配置是否生效。因为我看到你的日志还是只有下载服务的日志,不是下载服务日志与主进程回调日志一起的。

@wanghaihui
Copy link

06-27 21:15:04.017 8252-8252/com.wodi.who:filedownloader I/FileDownloader.FileDownloadProperties: init properties 1
load properties: http.lenient=FALSE; process.non-separate=FALSE; download.min-progress-step=65536; download.min-progress-time=2000; download.max-network-thread-count=3

@Jacksgong 你看这样是开了吗? 我的确是按照demo上来的,

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 这样说名没有开诶。要输出的那个process.non-separate=TRUE才是开。你再对照filedownloader.properties的文档:

  1. 看看文件名是否对
  2. 是否是放在了应用的assets目录下
  3. process.non-separate=true有没有错。

@wanghaihui
Copy link

wanghaihui commented Jun 28, 2017

log2.txt

@wanghaihui
Copy link

@Jacksgong 停留在了progress的99,没调用到completed

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 你升级到1.5.8,看看有没有修复你的问题。

@wanghaihui
Copy link

@Jacksgong 还是会遇到,我不是一个下载链接来回测,我是多个链接下载,来回切换,会出现

@Jacksgong
Copy link
Collaborator Author

Jacksgong commented Jun 28, 2017

@wanghaihui 你看看在demo project中看看会复现吗,我这边在demo project上始终复现不了。或者是可否编写一个可以复现的简单项目给我(可以发邮件给我 ( [email protected] ),或者push到github上给我),然后我这边认真复现下看看什么问题。

@wanghaihui
Copy link

@Jacksgong 我邮箱发你一个demo,你可以给看看,邮箱是[email protected]

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 好的,多谢。我这两天抽空看下。

@wanghaihui
Copy link

@Jacksgong 我还想问个问题,我两个apk都使用这个库时,第二个apk就安装不上了

@Jacksgong
Copy link
Collaborator Author

@wanghaihui FileDownloader并没有做过跨app共享或者其他的事情,是一个符合Android规范的简单的lib,对于不同的apk同时使用该库,完全没有任何影响,这个应该是其他原因导致。

@Jacksgong
Copy link
Collaborator Author

Jacksgong commented Jul 4, 2017

@wanghaihui 我找到你说的不同应用无法安装的原因了....是1.5.7引入的。一个broadcast权限的申明, 关注这个issue: #641

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 你的demo 4个按钮我下载下来在我的mi6上反复测试了一晚上都没有复现,明天我到公司借一台如你所说的vivo或者oppo试下。或者你加下我QQ(82780465),什么时候你有空了,我远程看下日志,你给复现下可以吗?

@wanghaihui
Copy link

@Jacksgong 恩 已经加你了,测试时清空下缓存数据,基本上来回三四次就会复现 我这里

@wanghaihui
Copy link

而且再提供个思路
07-05 12:15:00.497 32515-3594/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(0): [0, 1900615) 5701850
07-05 12:15:01.407 32515-3595/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[1] offset[3398976], consume[71]
07-05 12:15:01.457 32515-3596/com.wodi.who:filedownloader D/FileDownloader.FetchDataTask: require sync id[-385457779] index[2] offset[5460632], consume[14]
07-05 12:15:01.567 32515-3595/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(1): [1900616, 3801231) 5701850
07-05 12:15:01.567 32515-3596/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: the connection has been completed(2): [3801232, 0) 5701850
07-05 12:15:01.567 32515-3589/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
07-05 12:15:01.567 32515-3589/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE
07-05 12:15:01.567 32515-3589/com.wodi.who:filedownloader D/FileDownloader.DownloadLaunchRunnable: finish sub-task for [-385457779] TRUE FALSE

这个downloader进程的log,按理说这里代表下载完成,但是下面的log
07-05 12:17:04.997 31232-7622/com.wodi.who D/FileDownloader.FileDownloadMessenger: notify block completed [email protected]@cec3e68 FileDownloader-Flow-04
07-05 12:17:05.017 31232-31232/com.wodi.who D/FileDownload: blockComplete
07-05 12:17:05.017 31232-31232/com.wodi.who D/FileDownloader.FileDownloadMessenger: notify completed [email protected]@cec3e68
07-05 12:17:05.027 31232-31232/com.wodi.who D/FileDownload: completed
却并没有打印出来

所以就会一直卡在了完不成的界面,感觉是FileDownloadMessenger的问题,并没有notify

@wanghaihui
Copy link

07-05 16:23:48.619 2855-2855/com.conquer.manyouji D/FileDownloader.FileDownloadManager: request pause the task -14584498
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: java.io.SyncFailedException: fsync failed: EBADF (Bad file descriptor)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at java.io.FileDescriptor.sync(FileDescriptor.java:77)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.stream.FileDownloadRandomAccessFile.sync(FileDownloadRandomAccessFile.java:44)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.download.FetchDataTask.sync(FetchDataTask.java:210)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.download.FetchDataTask.pause(FetchDataTask.java:60)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.download.DownloadRunnable.pause(DownloadRunnable.java:60)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.download.DownloadLaunchRunnable.pause(DownloadLaunchRunnable.java:172)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.services.FileDownloadThreadPool.cancel(FileDownloadThreadPool.java:95)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.services.FileDownloadManager.pause(FileDownloadManager.java:208)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.services.FDServiceSharedHandler.pause(FDServiceSharedHandler.java:66)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.FileDownloadServiceSharedTransmit.pause(FileDownloadServiceSharedTransmit.java:65)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.FileDownloadServiceProxy.pause(FileDownloadServiceProxy.java:72)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.DownloadTaskHunter.pause(DownloadTaskHunter.java:419)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.DownloadTask.pause(DownloadTask.java:338)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.liulishuo.filedownloader.FileDownloader.pause(FileDownloader.java:297)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.conquer.manyouji.manager.FileDownloadManager$1.onDismiss(FileDownloadManager.java:73)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.conquer.manyouji.fragment.dialog.DownloadDialogFragment.onDismiss(DownloadDialogFragment.java:107)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at android.app.Dialog$ListenersHandler.handleMessage(Dialog.java:1323)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at android.os.Handler.dispatchMessage(Handler.java:102)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at android.os.Looper.loop(Looper.java:148)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at android.app.ActivityThread.main(ActivityThread.java:5628)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at java.lang.reflect.Method.invoke(Native Method)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:853)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:737)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: Caused by: android.system.ErrnoException: fsync failed: EBADF (Bad file descriptor)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at libcore.io.Posix.fsync(Native Method)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at libcore.io.BlockGuardOs.fsync(BlockGuardOs.java:143)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: at java.io.FileDescriptor.sync(FileDescriptor.java:74)
07-05 16:23:48.619 2855-2855/com.conquer.manyouji W/System.err: ... 22 more
07-05 16:23:48.629 2855-2855/com.conquer.manyouji D/FileDownloader.FetchDataTask: require sync id[-14584498] index[2] offset[5701850], consume[14]
07-05 16:23:48.629 2855-2855/com.conquer.manyouji D/FileDownloader.FileDownloadThreadPool: successful cancel -14584498 FALSE
07-05 16:23:48.629 2855-2855/com.conquer.manyouji D/FileDownloader.FileDownloadMessenger: notify begin [email protected]@8d56791
07-05 16:23:48.629 2855-2855/com.conquer.manyouji V/FileDownloader.DownloadTaskHunter: filedownloader:lifecycle:start com.liulishuo.filedownloader.DownloadTaskHunter@39176f6 by -2
07-05 16:23:48.629 2855-2855/com.conquer.manyouji V/FileDownloader.FileDownloadList: remove [email protected]@8d56791 left -2 0
07-05 16:23:48.629 2855-2855/com.conquer.manyouji D/FileDownloader.FileDownloadMessenger: notify paused [email protected]@8d56791
07-05 16:23:48.629 2855-2855/com.conquer.manyouji V/FileDownloader.DownloadTaskHunter: filedownloader:lifecycle:over com.liulishuo.filedownloader.DownloadTaskHunter@39176f6 by -2
07-05 16:23:48.639 2855-4517/com.conquer.manyouji D/FileDownloader.DownloadStatusCallback: High concurrent cause, Already paused and we don't need to call-back to Task in here, -14584498
07-05 16:23:49.319 2855-2855/com.conquer.manyouji D/PhoneWindow: DEBUG_SYSTEMUI:origin statusbar style
07-05 16:23:49.319 2855-2855/com.conquer.manyouji D/PhoneWindow: DEBUG_SYSTEMUI:windowDrawsFlag set
07-05 16:23:49.319 2855-2855/com.conquer.manyouji D/PhoneWindow: DEBUG_SYSTEMUI:IconColor=1
07-05 16:23:49.319 2855-2855/com.conquer.manyouji D/PhoneWindow: DEBUG_SYSTEMUI:StatusBarColor final set ff303f9f

@Jacksgong 还有遇到了这种情况

@wanghaihui
Copy link

@Jacksgong 请问啥时候有时间呢?我打log定位了一下
@OverRide
public void onCompleted(DownloadRunnable doneRunnable, long startOffset, long endOffset)
throws IOException {
if (paused) {
if (FileDownloadLog.NEED_LOG) {
FileDownloadLog.d(this, "the task[%d] has already been paused, so pass the" +
" completed callback", model.getId());
}
return;
}

    boolean allConnectionCompleted = false;

    final int doneConnectionIndex = doneRunnable == null ? -1 : doneRunnable.connectionIndex;
    if (FileDownloadLog.NEED_LOG) {
        FileDownloadLog.d(this, "the connection has been completed(%d): [%d, %d)  %d",
                doneConnectionIndex, startOffset, endOffset, model.getTotal());
    }

    if (isSingleConnection) {
        if (startOffset != 0 && endOffset != model.getTotal()) {
            FileDownloadLog.e(this, "the single task not completed corrected(%d, %d != %d) " +
                    "for task(%d)", startOffset, endOffset, model.getTotal(), model.getId());
        }

        allConnectionCompleted = true;
    } else {
        downloadRunnableList.remove(doneRunnable);
        if (downloadRunnableList.size() <= 0) {
            allConnectionCompleted = true;
        }
    }

    FileDownloadLog.d(this, "hai allConnectionCompleted : " + allConnectionCompleted);

    if (allConnectionCompleted) {
        FileDownloadLog.d(this, "hai all connection completed");
        // 此时应该所有的下载都已经完成
        statusCallback.onCompleted();
    }
}

在这个地方,出现99%的情况时,log如下:
07-06 16:46:29.244 17978-20506/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai allConnectionCompleted : false
07-06 16:46:29.244 17978-20505/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai allConnectionCompleted : false
07-06 16:46:29.474 17978-20507/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai allConnectionCompleted : false

此时,一共起了三个线程,第三个线程总会卡死在最后,所以完不成

@wanghaihui
Copy link

@Jacksgong 好吧 我找到原因了
if (isSingleConnection) {
if (startOffset != 0 && endOffset != model.getTotal()) {
FileDownloadLog.e(this, "the single task not completed corrected(%d, %d != %d) " +
"for task(%d)", startOffset, endOffset, model.getTotal(), model.getId());
}

        allConnectionCompleted = true;
    } else {
        FileDownloadLog.d(this, "hai several connection: " + downloadRunnableList.size());
        boolean result = downloadRunnableList.remove(doneRunnable);
        FileDownloadLog.d(this, "hai several connection: " + result);
        FileDownloadLog.d(this, "hai several connection: " + downloadRunnableList.size());
        if (downloadRunnableList.size() <= 0) {
            allConnectionCompleted = true;
        }
    }

我这样打了下log,最后出现99%的log如下:
07-06 17:06:16.954 8433-8833/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: 3
07-06 17:06:16.954 8433-8833/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: true
07-06 17:06:16.954 8433-8833/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: 2
07-06 17:06:16.954 8433-8834/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: 2
07-06 17:06:16.954 8433-8832/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: 2
07-06 17:06:16.954 8433-8832/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: true
07-06 17:06:16.954 8433-8834/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: true
07-06 17:06:16.954 8433-8832/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: 1
07-06 17:06:16.954 8433-8834/com.conquer.manyouji D/FileDownloader.DownloadLaunchRunnable: hai several connection: 1

downloadRunnableList.size() <= 0 这里永远也没走,所以allConnectionCompleted = false, 能不能给看看呀,还是我的写法有问题

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 谢谢哈,不好意思这两天有点忙,根据你新的日志信息我看看。

也十分欢迎PR。

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 挺奇怪的,QQ上聊先吧。

@Jacksgong
Copy link
Collaborator Author

@wanghaihui 感谢你的配合🙏~

已经找到原因,这个是一个多线程安全问题导致。

具体原因

是多个分块线程同时完成下载回调到DownloadLaunchRunnable#onComplete中的时候,当有两个线程同时访问其中的downloadRunnableList.remove(doneRunnable)时可能出现这个问题。

深层原因

翻看downloadRunnableList.remove(doneRunnable)中的 ArrayList#remove(Object)源码:

public boolean remove(Object o) {
    if (o == null) {
        for (int index = 0; index < size; index++)
            if (elementData[index] == null) {
                fastRemove(index);
                return true;
            }
    } else {
        for (int index = 0; index < size; index++)
           // 问题就出在当两个线程同时访问这段代码段时
           // 假设第一个线程要移除的是0,第二个线程要移除的是1
           // 假设队列数据是[0, 1, 2, 3]
           // 异常情况一:当第二个线程刚遍历过0时,还没有开始对比1,
           // 第一个线程刚好执行了fastRemove将0移除,
           // 此时队列变为了[1,2,3],就这样错过了需要移除的内容。
            if (o.equals(elementData[index])) {
                fastRemove(index);
                return true;
            }
    }
    return false;
}

private void fastRemove(int index) {
    modCount++;
    int numMoved = size - index - 1;
    // 异常情况二:当两个线程都同时到达这里,此时第二个计算出来要移动的位置必然是错误的
    if (numMoved > 0)
        System.arraycopy(elementData, index+1, elementData, index,
                         numMoved);
    elementData[--size] = null; // clear to let GC do its work
}

解决方案

保持downloadRunnableList.remove(doneRunnable)线程安全,今晚会发布新版本修复。

@Jacksgong Jacksgong added bug and removed need-verify labels Jul 6, 2017
@Jacksgong Jacksgong modified the milestone: 1.6.0 Jul 6, 2017
@Jacksgong
Copy link
Collaborator Author

Jacksgong commented Jul 6, 2017

This is the thread-safe problem.

Reason

There are more than one connections to download one task on different threads, and when there are
several threads finish downloading and invoking DownloadLaunchRunnable#onComplete method
simultaneously and more than one thread invoking downloadRunnableList.remove(doneRunnable) on the method simultaneously may occur such problem.

Digger cause

Refer to ArrayList#remove(Object) of downloadRunnableList.remove(doneRunnable):

public boolean remove(Object o) {
    if (o == null) {
        for (int index = 0; index < size; index++)
            if (elementData[index] == null) {
                fastRemove(index);
                return true;
            }
    } else {
        for (int index = 0; index < size; index++)
           // when there are two threads working on here simultaneously
           // It assume the data on this list is [0, 1, 2, 3].
           // and assume the first thread want to remove '0', the second thread want to remove '1'
           // problem one:when the second thread just check the '0' and it hasn't started to check '1'
           // then the first thread is just executed the fastRemove method to remove '0' from the list
           // so the list is changed to [1, 2, 3],then the first thread miss chance to remove '1'.
            if (o.equals(elementData[index])) {
                fastRemove(index);
                return true;
            }
    }
    return false;
}

private void fastRemove(int index) {
    modCount++;
    int numMoved = size - index - 1;
    // problem two: when the two threads are working on here simultaneously, then the numMoved value must be wrong for the next thread.
    if (numMoved > 0)
        System.arraycopy(elementData, index+1, elementData, index,
                         numMoved);
    elementData[--size] = null; // clear to let GC do its work
}

Solution

keepdownloadRunnableList.remove(doneRunnable) method thread-safe.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants