aMule Forum
English => en_Bugs => Topic started by: gav616 on April 16, 2010, 12:57:20 AM
-
I saw the fix for network blocking in '10086', I realise that it now downloads a new ipfilter or reloads the current one if not newer, then amule initialises 'connecting' in that order,.
I like this method, but I'm getting a problem in '10089';
--
I have 'Auto-update ipfilter at startup' checked, and have a URL entered.
At startup the IPfilter takes 5+ minutes to either check for a newer file or to reload the current one, making amule wait for this process to finish before connecting to ed2k or kad.
As I said above, I do actually prefer this method in waiting for the filter to update first before connecting, but something is causing it to just pause and not make a decision.
p.s. 1
BTW, the url for the filter is fine and downloads externally with firefox/wget/aria2 etc...
p.s. 2
I think the update on start-up is conflicting with the reloading on startup, because when I manually reloaded the filter, it finally connects but then gets the new filter that it found.
-
Please enable ThreadScheduler verbose debugging to get an idea what's happening.
I suspect the following:
- HTTP download starts (in an extra thread)
- meanwhile thread scheduler finds AICH hashing as first thread ready to be executed and starts that
- IP filter loading (and connection is delayed until AICH finishes)...
That's it?
-
Please enable ThreadScheduler verbose debugging to get an idea what's happening.
I suspect the following:
- HTTP download starts (in an extra thread)
- meanwhile thread scheduler finds AICH hashing as first thread ready to be executed and starts that
- IP filter loading (and connection is delayed until AICH finishes)...
That's it?
yeah, i think (testing ATM...)
It seems fine when Skipping the download, but when it finds a newer one that's when it stalls..
Not confirmed yet, I'm testing..
-
Should be fixed in 10113, please verify.
-
Should be fixed in 10113, please verify.
I still need to compile with 'debugging' but its definitely not fixed yet.
notice the time difference from starting aMuleD and loading the filter..
2010-06-08 13:05:18: Logging to stdout enabled
2010-06-08 13:05:18: Initialising aMuleD SVN using wxGTK2 v2.8.11 (Snapshot: rev. 10204)
2010-06-08 13:05:18: Checking if there is an instance already running...
2010-06-08 13:05:18: No other instances are running.
2010-06-08 13:05:19: Creditfile loaded, 5335 clients are known
2010-06-08 13:05:19: - Credits expired for 135 clients!
2010-06-08 13:05:19: *** TCP socket (ECServer) listening on 127.0.0.1:54712
2010-06-08 13:05:19: ListenSocket: Ok.
2010-06-08 13:05:19: Created Client UDP-Socket at port 54672
2010-06-08 13:05:19: Loading temp files from /home/gav/.aMule/Temp.
2010-06-08 13:05:19: Loading PartFile 1 of 1
2010-06-08 13:05:19: All PartFiles Loaded.
2010-06-08 13:05:19: Found 1 part file
2010-06-08 13:05:19: Adding file /home/gav/.aMule/Temp/002.part.met to shares
2010-06-08 13:05:19: Found 76 known shared files
2010-06-08 13:05:19: amuled: OnInit - starting timer
2010-06-08 13:18:20: Successfully updated ipfilter.dat
2010-06-08 13:18:20: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-06-08 13:18:21: Loaded 196342 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-06-08 13:18:21: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-06-08 13:18:21: IP filter is ready
!2010-06-08 13:18:21: Connecting
2010-06-08 13:18:21: Read 197 Kad contacts
!2010-06-08 13:18:39: Connected to Kad (firewalled)
!2010-06-08 13:19:29: Connected to Kad (ok)
An 'aria2' of the same ipfilter takes 0.5-1 seconds to download.
-
Please repost with verbose debug logging for thread scheduler and ip filter enabled.
(No need to try anything newer than you had for this issue btw.)
-
2010-06-09 12:41:10: amuleAppCommon.cpp(325): Logging to stdout enabled
2010-06-09 12:41:10: amuleAppCommon.cpp(329): Initialising aMuleD SVN using wxGTK2 v2.8.11 (Snapshot: rev. 10212)
2010-06-09 12:41:10: amuleAppCommon.cpp(375): Checking if there is an instance already running...
2010-06-09 12:41:11: amuleAppCommon.cpp(406): No other instances are running.
2010-06-09 12:41:11: ClientCreditsList.cpp(159): Creditfile loaded, 5389 clients are known
2010-06-09 12:41:11: ClientCreditsList.cpp(162): - Credits expired for 42 clients!
2010-06-09 12:41:11: ThreadScheduler.cpp(116): ThreadScheduler: Scheduler created.
2010-06-09 12:41:11: ThreadScheduler.cpp(229): ThreadScheduler: Task scheduled: Load IPFilter -
2010-06-09 12:41:11: ExternalConn.cpp(328): *** TCP socket (ECServer) listening on 127.0.0.1:54712
2010-06-09 12:41:11: ListenSocket.cpp(66): ListenSocket: Ok.
2010-06-09 12:41:11: MuleUDPSocket.cpp(81): Created Client UDP-Socket at port 54672
2010-06-09 12:41:11: ThreadScheduler.cpp(79): ThreadScheduler: Starting scheduler
2010-06-09 12:41:11: ThreadScheduler.cpp(161): ThreadScheduler: Scheduler thread started
2010-06-09 12:41:11: DownloadQueue.cpp(108): Loading temp files from /home/gav/.aMule/Temp.
2010-06-09 12:41:11: DownloadQueue.cpp(127): Loading PartFile 1 of 2
2010-06-09 12:41:11: DownloadQueue.cpp(127): Loading PartFile 2 of 2
2010-06-09 12:41:11: DownloadQueue.cpp(159): All PartFiles Loaded.
2010-06-09 12:41:11: DownloadQueue.cpp(164): Found 2 part files
2010-06-09 12:41:11: SharedFileList.cpp(335): Adding file /home/gav/.aMule/Temp/001.part.met to shares
2010-06-09 12:41:11: SharedFileList.cpp(335): Adding file /home/gav/.aMule/Temp/002.part.met to shares
2010-06-09 12:41:11: SharedFileList.cpp(364): Found 77 known shared files
2010-06-09 12:41:11: ThreadScheduler.cpp(229): ThreadScheduler: Task scheduled: AICH Syncronizing -
2010-06-09 12:41:11: amuled.cpp(688): amuled: OnInit - starting timer
2010-06-09 12:41:11: ThreadScheduler.cpp(264): ThreadScheduler: Entering scheduling loop
2010-06-09 12:41:11: ThreadScheduler.cpp(274): ThreadScheduler: Resorting tasks
2010-06-09 12:41:11: ThreadScheduler.cpp(288): ThreadScheduler: Current task: Load IPFilter -
2010-06-09 12:47:12: IPFilter.cpp(524): Successfully updated ipfilter.dat
2010-06-09 12:47:12: IPFilter.cpp(121): Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-06-09 12:47:13: IPFilter.cpp(338): Loaded 196426 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-06-09 12:47:13: IPFilter.cpp(338): Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-06-09 12:47:14: IPFilter.cpp(557): IP filter is ready
!2010-06-09 12:47:14: IPFilter.cpp(567): Connecting
2010-06-09 12:47:15: RoutingZone.cpp(208): Read 188 Kad contacts
2010-06-09 12:47:15: ThreadScheduler.cpp(308): ThreadScheduler: Completed task 'Load IPFilter', 1 tasks remaining.
2010-06-09 12:47:15: ThreadScheduler.cpp(324): ThreadScheduler: Last task, calling OnLastTask
2010-06-09 12:47:15: ThreadScheduler.cpp(274): ThreadScheduler: Resorting tasks
2010-06-09 12:47:15: ThreadScheduler.cpp(288): ThreadScheduler: Current task: AICH Syncronizing -
2010-06-09 12:47:15: ThreadScheduler.cpp(308): ThreadScheduler: Completed task 'AICH Syncronizing', 0 tasks remaining.
2010-06-09 12:47:15: ThreadScheduler.cpp(324): ThreadScheduler: Last task, calling OnLastTask
2010-06-09 12:47:15: ThreadScheduler.cpp(278): ThreadScheduler: No more tasks, stopping
2010-06-09 12:47:15: ThreadScheduler.cpp(329): ThreadScheduler: Leaving scheduling loop
!2010-06-09 12:47:16: amule.cpp(1908): Connected to Kad (firewalled)
!2010-06-09 12:48:10: amule.cpp(1906): Connected to Kad (ok)
-
Could it be that your IP filter takes 6 min to download ? :o
I see I have to go over that. The original idea was, loading the filter takes longer than downloading it, so no need to first load it, then download it, then load it again. With the new load code this has changed somewhat.
Still, if I change the behavior, aMule will connect using the old IP filter even if "update filter on startup" is selected. This is kind of a security issue, so I don't like that very much. :-\
-
This is kind of a security issue, so I don't like that very much. :-\
Well, what if the download totally fails for some reason? That means either use old filter or abort... I don't consider it that serious, and first loading the old filter and later replacing with the new would definiately give better user experience.
If it's that important for someone to first update IP filter, and only then connect, the best solution to achieve it is using a wrapper that updates the filter and starts aMule only when the update is done. Or we can add a config option "Don't connect until the filter is up-to-date", which I don't like at all and would consider only as a last resort.
-
We could just separate all IPFilter stuff in a new tab, and make "Don't connect until the ipfilter is updated" a sub-checkbox of "Update on startup", as it makes some sense. Off by default, of course.
-
first loading the old filter and later replacing with the new would definiately give better user experience.
10225
-
first loading the old filter and later replacing with the new would definiately give better user experience.
10225
Works perfectly :D
I still don't know why it took so long though, It was definitely not a 'slow source' problem...
2010-07-02 13:24:20: Logging to stdout enabled
2010-07-02 13:24:20: Initialising aMuleD SVN using wxGTK2 v2.8.11 (Snapshot: rev. 10227)
2010-07-02 13:24:20: Checking if there is an instance already running...
2010-07-02 13:24:20: No other instances are running.
2010-07-02 13:24:21: Creditfile loaded, 4341 clients are known
2010-07-02 13:24:21: - Credits expired for 474 clients!
2010-07-02 13:24:21: *** TCP socket (ECServer) listening on 127.0.0.1:54712
2010-07-02 13:24:21: ListenSocket: Ok.
2010-07-02 13:24:21: Created Client UDP-Socket at port 54672
2010-07-02 13:24:21: Loading temp files from /home/gav/.aMule/Temp.
2010-07-02 13:24:21: Loading PartFile 1 of 2
2010-07-02 13:24:21: Loading PartFile 2 of 2
2010-07-02 13:24:21: All PartFiles Loaded.
2010-07-02 13:24:21: Found 2 part files
2010-07-02 13:24:21: Adding file /home/gav/.aMule/Temp/001.part.met to shares
2010-07-02 13:24:21: Adding file /home/gav/.aMule/Temp/002.part.met to shares
2010-07-02 13:24:21: Found 77 known shared files
2010-07-02 13:24:21: amuled: OnInit - starting timer
2010-07-02 13:24:21: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-07-02 13:24:21: Loaded 196402 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-07-02 13:24:21: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-07-02 13:24:21: IP filter is ready
!2010-07-02 13:24:21: Connecting
2010-07-02 13:24:21: Read 200 Kad contacts
!2010-07-02 13:24:23: Connected to Kad (firewalled)
2010-07-02 13:24:23: New external connection accepted
2010-07-02 13:24:23: Connecting client: amule-remote 0x0001
2010-07-02 13:24:23: Access granted.
!2010-07-02 13:24:44: Connected to Kad (ok)
2010-07-02 13:24:58: Successfully updated ipfilter.dat
2010-07-02 13:24:58: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-07-02 13:24:59: Loaded 196988 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-07-02 13:24:59: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-07-02 13:24:59: IP filter is ready
ahhh well... it works in a good way now, anyways.. :)
-
sorry guys.
I've just noticed, from start-up it still takes ages (7mins) to : download an updated ipfilter from the 'URL' then to see it 'Loaded' in amule.
It takes 1-3 seconds from a 'aria2' download.
Does aMule inspect the file and reorder it in alphabetical or something before injecting it?
-
What's the URL?
-
ipfilter.dat.gz
from
http://tbg.iblocklist.com/Lists/
-
7 sec for download, 3 sec for filter load (debug build). ???
What exactly is taking the time? Please check your log. And which SVN version are you using?
-
it only seems to happen when there's an update of the original ipfilter in place, at fresh start-up.
so I guess for you (and me) to test, you'll have to wait 1-3 days to get an updated ipfilter from that url.
buts it's not the time it gets it, its the time it replaces it with the old one that's used, while it's checking and getting the new one at start-up.
But, anyway... i'll re-compile with debug and wait for an-updated url.
p.s.
what debug settings in amule is advised?
p.p.s
just to compare latest SVN to my last log entry
previous log 38sec
2010-07-02 13:24:21: amuled: OnInit - starting timer
2010-07-02 13:24:21: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-07-02 13:24:21: Loaded 196402 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-07-02 13:24:21: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-07-02 13:24:21: IP filter is ready
!2010-07-02 13:24:21: Connecting
2010-07-02 13:24:21: Read 200 Kad contacts
!2010-07-02 13:24:23: Connected to Kad (firewalled)
2010-07-02 13:24:23: New external connection accepted
2010-07-02 13:24:23: Connecting client: amule-remote 0x0001
2010-07-02 13:24:23: Access granted.
!2010-07-02 13:24:44: Connected to Kad (ok)
2010-07-02 13:24:58: Successfully updated ipfilter.dat
2010-07-02 13:24:58: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-07-02 13:24:59: Loaded 196988 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-07-02 13:24:59: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-07-02 13:24:59: IP filter is ready
latest SVN (10257) 5 minutes
2010-07-28 18:16:54: amuled: OnInit - starting timer
2010-07-28 18:16:54: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-07-28 18:16:55: Loaded 201150 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-07-28 18:16:55: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-07-28 18:16:55: IP filter is ready
!2010-07-28 18:16:55: Connecting
2010-07-28 18:16:55: Read 198 Kad contacts
!2010-07-28 18:16:55: Kad started.
!2010-07-28 18:16:56: Kad stopped.
!2010-07-28 18:16:56: Connected to Kad (firewalled)
2010-07-28 18:16:59: New external connection accepted
2010-07-28 18:16:59: Connecting client: amule-remote 0x0001
2010-07-28 18:16:59: Access granted.
!2010-07-28 18:18:05: Connected to Kad (ok)
2010-07-28 18:18:48: External connection closed.
2010-07-28 18:19:28: New external connection accepted
2010-07-28 18:19:28: Connecting client: amule-remote 0x0001
2010-07-28 18:19:28: Access granted.
2010-07-28 18:22:15: Successfully updated ipfilter.dat
2010-07-28 18:22:15: Loading IP filters 'ipfilter.dat' and 'ipfilter_static.dat'.
2010-07-28 18:22:16: Loaded 201712 IP-ranges from '/home/gav/.aMule/ipfilter.dat'.
2010-07-28 18:22:16: Loaded 0 IP-ranges from '/home/gav/.aMule/ipfilter_static.dat'.
2010-07-28 18:22:16: IP filter is ready
-
Well, it's not the loading of the filter that takes the time. Probably the download.
If you wait until everything is up, then delete ipfilter.dat and click "update now" in preferences/security - do you also get the insane delay?
Please run a debug build and enable "http" and "ipfilter". And add an extra debug line:
Index: HTTPDownload.cpp
===================================================================
--- HTTPDownload.cpp (revision 10257)
+++ HTTPDownload.cpp (working copy)
@@ -264,6 +264,7 @@
evt.SetExtraLong(download_size);
wxPostEvent(m_companion, evt);
#endif
+ AddDebugLogLineN(logHTTP, CFormat(wxT("Download progress: %i")) % total_read);
}
}
} while (current_read && !TestDestroy());
-
I've noticed the ipfilter at start-up always waits until KAD is 'ok' to then check for the update.
So, if I've offlined for a couple of days it takes about 2-5mins to get enough contacts together to get a highid in KAD, which is the same time I've been complaining about in which it takes the ipfilter to check/update..
I request a reverting back to checking/updating the ipfilter stuff 'before' connecting.
-
Your post above shows the delay to occur after Kad switches from firewalled to ok, so I don't believe your conclusion is correct.
Please help me tracking down the problem by answering the questions from my previous post.