Bug 187698 - Azureus "logging to file" option eats space very rapidly
Azureus "logging to file" option eats space very rapidly
Status: CLOSED NEXTRELEASE
Product: Fedora
Classification: Fedora
Component: gcc (Show other bugs)
5
x86_64 Linux
medium Severity medium
: ---
: ---
Assigned To: Anthony Green
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2006-04-02 18:25 EDT by Andy Burns
Modified: 2007-11-30 17:11 EST (History)
3 users (show)

See Also:
Fixed In Version: azureus-2.4.0.3-0.20060328cvs_2
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2006-04-17 21:28:00 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
First 2MB of log file (2.00 MB, text/plain)
2006-04-04 19:44 EDT, Jon Burgess
no flags Details
Archive containing test program and response causing the problem (4.57 KB, application/octet-stream)
2006-04-13 21:20 EDT, Jon Burgess
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
GNU Compiler Collection 27171 None None None Never

  None (edit)
Description Andy Burns 2006-04-02 18:25:20 EDT
Description of problem:
While exracting log information to report an earlier bug, I tried to use
Azureus's "logging to file" option, with a file of /home/andy/az.log, initially
I thought it wasn't working at all, then I realised the field specified a
foldername not a filename, so I created a folder called az.log inside /home/andy
and azureus then created a file called az.log inside that folder.

It very soon became apparent that something was still wrong, the file had grown
to 3GB within a few seconds and 11GB before I could kill the process.

the file doesn't contain any sensible information, viewed with hexdump.

Version-Release number of selected component (if applicable):
azureus 2.4.0.0-0.20060209cvs_1.fc5
kernel 2.6.16-1.2069_FC5
gij 4.1.0-3

How reproducible:
100%

Steps to Reproduce:
1. run azureus
2. enable logging option
3. enable logging to disk option, to a folder that does exist
  
Actual results:
exponentially growing log file!
Comment 1 Anthony Green 2006-04-02 21:03:25 EDT
(In reply to comment #0)
> Actual results:
> exponentially growing log file!

Fun!

Which version are you using?  I can't reproduce this on x86 with
azureus-2.4.0.3-0.20060328cvs_2.

If you're not using that version, could you please update and try again?  If you
can still reproduce, then I'll try on x86_64.

Thanks!
Comment 2 Anthony Green 2006-04-02 21:04:26 EDT
(In reply to comment #1)
> Which version are you using?  I can't reproduce this on x86 with
> azureus-2.4.0.3-0.20060328cvs_2.

Oh - stupid me.  You told me what version you're using.  Please update and try
again.

Thanks!
Comment 3 Andy Burns 2006-04-03 08:13:47 EDT
Updated and it still mis-behaves, so it's either a 64v32bit issue, or perhaps
you've got a rawhide version of gcj/gij on your machine? I've only taken
upgraqded as far as core-updates and updates-testing.
Comment 4 Andy Burns 2006-04-03 08:20:22 EDT
Hmm, just cleaned the junk out of the az.log folder and the az.log file it
re-creates now grows properly and has good contents, wierd? 

Comment 5 Anthony Green 2006-04-03 08:35:13 EDT
Strange.  Let's close this for now.  Maybe it will never reappear with the new
version.  We can reopen it if it does.
Comment 6 Jon Burgess 2006-04-04 19:44:20 EDT
Created attachment 127318 [details]
First 2MB of log file

I see this too on azureus-2.4.0.3-0.20060328cvs_3.fc5.x86_64.rpm. I saw this
before on the old version and was hoping that it might be fixed by the update.
What I see is that the program will run fine for a while (maybe 30 minutes)
then it'll start filling the az.log with junk _very_ rapidly (1GB+/minute).

[jburgess@shark logs]$ ls -l
total 2797068
-rw-rw-r-- 1 jburgess jburgess 2858760691 Apr  5 00:21 az.log
-

I've attached the first 2MB of my az.log file. For the first few minutes
everything looks fine. Then the output becomes garbled and then nothing
recognisable at all.

Here is the bit where it becomes garbage...

23:19:08.857 0 peer    In: has sent their handshake . . . . . . . . . . . . . .
. . . . . . . . . . . . . . . . . . . . . . . . . . . . TorrentDLM:
'bordeaux-DVD-i386'; Peer: R: 195.94.216.58: 2782 [Azureus 2.4.0.2]
23:19:08.938 0 tracker Forcing tracker announce now via
TRTrackerBTAnnouncerImpl::update::-1,DownloadManagerImpl::informStarted::-1,DownloadManagerController::startDownload::-1
Torrent: 'bordeaux-binary-x86_64'
23:19:08.940 0 tracker Tracker Announcer is sending a start Request . . . . . .
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
. . . . . . . . .Torrent: 'bordeaux-binary-x86_64'
23:19:08.941 0 tracker Tracker Announcer is Requesting:
http://torrent.linux.duke.edu:6969/announce?info_hash=%3A%C2%8D%DE%13%EFMZ%09%BC%C3%CE%06_Gmb%8C%01%3C&peer_id=-AZ2403-57ilMeXqjjEI&port=57934&uploaded=0&downloaded=0&left=0&event=started&numwant=79&no_peer_id=1&compact=1&key=HxHRsVSk

Torrent: 'bordeaux-binary-x86_64'
23:19:09.267 0 tracker Tracker Announcer
[http://torrent.linux.duke.edu:6969/announce] has received :
d8:completei57e10:incompletei24e8:intervali1800e5:peers270:ފϥk"]a=PfʨCT
Comment 7 Jon Burgess 2006-04-04 19:53:56 EDT
I wiped the log and restarted Azureus. This time it broke almost immeadiately.
It seems like it always breaks with the "Tracker Announcer" message:

23:55:48.101 0 tracker Next tracker announce (adjusted) will be in 1790s . . . .
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . Torrent:
'bordeaux-DVD-x86_64'

23:55:48.199 0 nwman   Incoming TCP stream from [152.3.220.165:52060] recognized
as known byte pattern: 13426974 546F7272 656E7420 70726F74 6F636F6C 00000000
00000000 30EDCC0D B535DBD6 2595433A E260FBA9 B94B7AF1

23:55:48.287 0 tracker Tracker Announcer
[http://torrent.linux.duke.edu:6969/announce] has received :
d8:completei734e10:incompletei440e8:intervali1800e5:peers150:SG;P0TS;W
Comment 8 Anthony Green 2006-04-13 15:41:11 EDT
I've reproduced this.

It looks like we're creating a corrupt "message" in 
org.gudy.azureus2.core3.tracker.client.impl.bt.TRTrackerBTAnnouncerImpl.announceHTTP

Eventually we get to...
(gdb) down
#6  0x0151439f in
org.gudy.azureus2.core3.logging.impl.FileLogging.logToFile(java.lang.String)
(this=@4ceb60, str=@450b3c0)
    at org/gudy/azureus2/core3/logging/impl/FileLogging.java:162
162                                             pw.print(str);
(gdb) p str
$34 = warning: RTTI symbol not found for class 'java::lang::String'
java.lang.Stringwarning: RTTI symbol not found for class 'java::lang::String'

 "14:30:58.513 0 tracker Tracker Announcer
[http://torrent.linux.duke.edu:6969/announce] has received :
d8:completei683e10:incompletei373e8:intervali1800e5:peers372:Cm\u001a<(5A\u000fc\u001aV}Z\u001aT\u001aB\u0012]\u0715s\u0002\u001aS\u0000(\u0000U\u0015\u001a\u00180{6D\u0424\u0005"...

The text after "received :" is the corrupted message.

"message" is a byte buffer filled by reading from http connection - possibly via
GZIPInputStream.  My best guess at this point is that this is a bug in
GZIPInputStream or our zip implementation.  But, I could be very wrong. 

I'll try to debug a little more..
Comment 9 Jon Burgess 2006-04-13 15:50:10 EDT
I'm not so sure it is a bug in the decoder. I believe the data following the
text is a list of peers which is binary encoded (i'm not sure if is simply
groups of 4 bytes per IP or something more complicated). The bottom line is, I
think the remaining contents of the message really is binary data and azureus
probably shouldn't be trying to print it at all. 

I traced this down into the logging class and it looks like the code tries to
interpret this in the default character encoding (which for is LANG=en_GB.UTF-8).

I found that If I set "LANG=C azureus" then the problem didn't occur, so i'm
guessing that something in the UTF8 processing goes crazy when it finds the
binary data. OTOH - the Sun JVM is obviously OK with this so it it arguably a
bug in gij/classpath code that it can't handle what is presumably a bad UTF8 stream.



Comment 10 Jon Burgess 2006-04-13 16:30:47 EDT
Looking at the Azureus source shows that the list of peers can either be stored
in text form or in a compact form which is literally a sequence of 6 bytes (4
for IP adress, 2 for port number). See TRTrackerBTAnnouncerImpl.java and seach
for "meta_peers_peek" there is code to handle both the non-compact and compact
cases.
Printing the message as a string makes more sense if the messages is in the
non-compact form.

BTW - Were you running on x86-64 when you reproduced this? I see that both the
original poster and myself are running on x86-64.
I had a quick look through the gcj charset and stream handling code and it
looked like it tried to protect against itself invalid input but obviously
something isn't working quite as it should.
Comment 11 Anthony Green 2006-04-13 16:52:42 EDT
(In reply to comment #10)
> Looking at the Azureus source shows that the list of peers can either be stored
> in text form or in a compact form which is literally a sequence of 6 bytes (4
> for IP adress, 2 for port number). See TRTrackerBTAnnouncerImpl.java and seach
> for "meta_peers_peek" there is code to handle both the non-compact and compact
> cases.
> Printing the message as a string makes more sense if the messages is in the
> non-compact form.

Interesting.  We should try to create a small test case from those messages.  I
guess azureus can be modified to write those messages to separate files.   If
you are motivated, that would be a great help.  I don't think I can get to it
for a few days.

> BTW - Were you running on x86-64 when you reproduced this? I see that both the
> original poster and myself are running on x86-64.

I reproduced on 32-bit x86. 

> I had a quick look through the gcj charset and stream handling code and it
> looked like it tried to protect against itself invalid input but obviously
> something isn't working quite as it should.

I just spoke to tromey and he says this code has a history of problems.
A test string is the next step.

Thanks for your help!

Comment 12 Jon Burgess 2006-04-13 21:20:09 EDT
Created attachment 127735 [details]
Archive containing test program and response causing the problem

I'm new to java so please forgive the coding in this example. I attempted to
put together a program which demonstrates the problem. This attempts to read
the contents of "peers.bin" and writes it to "log.txt". I've archived the files
up and attached them in an archive.

peers.bin was created from the HTTP payload from the tracker which caused the
Azureus logging to go crazy. I used etheral to capture the packets and create
the file.

If I run this with the following command then stop it after a couple of seconds
then the output file "log.txt" is already 10MB+

$ /usr/bin/java -Djava.ext.dirs=/usr/lib/jvm/java-1.4.2-gcj-1.4.2.0/jre/lib/ext
-jar test2.jar

If I replace peers.bin with another ASCII file then it the text to log.txt OK.
Comment 13 Anthony Green 2006-04-14 15:13:21 EDT
(In reply to comment #12)
> Created an attachment (id=127735) [edit]
> Archive containing test program and response causing the problem

Great work Jon!  I've filed a bug against GCC (27171), which is now referenced
below.

AG
Comment 14 Tom Tromey 2006-04-17 17:41:31 EDT
I checked in a fix to GCC svn.
It will be in GCC 4.1.1; most like Jakub will pull it into the next
set of GCC RPMs.

The problem turned out to be in the handling of isolated low surrogates,
when converting to UTF-8.
Comment 15 Anthony Green 2006-04-17 21:28:00 EDT
(In reply to comment #14)
> I checked in a fix to GCC svn.

Thanks Tom! I'm closing this bug.

Note You need to log in before you can comment on or make changes to this bug.