Incorrect error message when failing to write to disk

Ask for help and report issues not specific to either the Mac OS X or GTK+ versions of Transmission
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Incorrect error message when failing to write to disk

Post by boise »

I set up Transmission to keep the torrents on my DATA disk while downloading, and to move the files to my NFS-mounted MyCloud NAS drive after completing the download. This worked when I set it up, but after that it worked some times and failed early on at other times.

The error message I got when it failed was "Error: Permission denied (/home/bosse/MyCloud/New/<the-torrent>)" which was no great surprise to me since I hardly knew what I was doing when I mounted the NAS server through NFS (at /home/bosse/MyCloud). However, I couldn't find any problem with the mount. It worked just fine as far as I could tell.

It took me quite a long time to realize that the error message that Transmission gave me was all wrong. The problem was not a permission problem, and it was not with the MyCloud mount. In reality, the problem was that I didn't have an auto-mount for the DATA drive, meaning that the downloads worked when I had mounted the DATA drive "manually" by opening it in Nautilus (for unrelated reasons), and failed when I had not done so.

Recipe:
1. Set up Transmission to keep a torrent on device A while downloading it, and to move it to device B when the download is complete.
2. Make sure that device A is not mounted.
3. Download a torrent file.

What will happen is that when Transmission has downloaded the first couple of MB and attempts to write them to device A, it will fail since device A is not mounted. The problem is that it will tell you that the error is "permission denied" on device B (which it probably hasn't even tried to access yet), while it is actually device A that failed.

In other words, this is not a bug with the downloading or moving of torrents - it is "only" a totally incorrect error message from Transmission. I would still consider it pretty serious since it makes isolating the problem quite difficult even though it is actually trivial to fix.

I should probably add that this problem is not in any way related to the fact that "device B" in my case was a network drive. The way that I found the solution was when I changed the "final destination" to my personal ~/Download directory and still got the Permission denied error.

I can also add that after adding an auto-mount entry for my DATA drive in /etc/fstab, everything works perfectly.
x190
Posts: 5094
Joined: Sun Nov 30, 2008 4:59 am

Re: Incorrect error message when failing to write to disk

Post by x190 »

Transmission just reports the error as it is received from the OS.
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Re: Incorrect error message when failing to write to disk

Post by boise »

x190 wrote:Transmission just reports the error as it is received from the OS.
I'm sorry, but I find that very hard to believe.

Why on earth would the OS (Ubuntu 14.04 in this case) report a "permission denied" error on device B (to follow my previous example) when:
  1. (This is just an informed guess, but) Transmission has probably not even tried to access device B when I gives the error message.
  2. There is no problem at all for Transmission to access device B when it actually tries to (which it does a bit later when moving the downloaded file).
  3. There really is a problem with accessing the other device (device A), that also happens to be the device that Transmission should be trying to write to at the time of the error.
Basically, the error message is correct, except for that it points out the wrong device.

I'll take a look at the source code in a while and see if I can spot the problem.

Edit: I mixed up "device A" and "B" above :roll:
Last edited by boise on Wed Sep 10, 2014 10:21 pm, edited 1 time in total.
rb07
Posts: 1400
Joined: Sun Aug 24, 2008 3:14 am

Re: Incorrect error message when failing to write to disk

Post by rb07 »

You are right. Don't take the answers you receive too seriously.

The main problem in your post is that you didn't give details, so other people have to guess... and those guesses are probably wrong.

My guess: you are using Transmission-GTK on Linux. There's a forum specially for that client.

As I said, you are right:
  • The error message is wrong, but the error is probably only on the GTK client, so nobody else using other clients does see that error.
  • The error is only on the message. Which is what you imply by your point (1) above, the write failure was in the "incomplete" directory, but the error used the final destination directory in the message.
  • The important part is the solution, which you already posted: use auto-mount, or just mount the remote file system at boot.
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Re: Incorrect error message when failing to write to disk

Post by boise »

Good points there, rb07. You are absolutely correct in that I failed to provided enough information (any information, really) about where I saw the problem. My bad :oops:

My (poor) excuse is that I a) was really tired when I posted, and b) hadn't realized that there are so many different parts of Transmission. I just run what came pre-installed with Ubuntu 14.04, which I now know is Transmission-GTK v2.82.

Anyway, since I started it here, I'll post my findings of the bug too, and then I'll find the correct forum and just link to this post. The bug is actually in a routine in libtransmission, so I suppose that it may affect other clients than GTK, but I'm too tired to check that (quarter past midnight here in Sweden, and early work day tomorrow - eh... I mean today :) ).

So - I had a look at the source code, and I found the bug (or "oversight" or whatever you want to call it).

In the readOrWritePiece() function in libtransmission/inout.c, when the call to the readOrWriteBytes() function returns an error code, tr_torrentSetLocalError() is called to register the error.

The problem lies in the parameters sent in that call to torrentSetLocalError(). The error code is correctly translated to a string with tr_strerror(err), but the value of the "path" variable is wrong.

The "path" variable is created on the line above (line 227 in v2.84) through a call to tr_buildPath(), and the bug is that the first argument in that call (the path to the file for which the error occurred) is incorrect. More specifically, the parameter is sent as tor->downloadDir, but it is far from certain that this is where the file error actually occurred. In my case, for example, the error really occurred in tor->incompleteDir.

I suppose it would work to call tr_torrentFindFile2() to get the true path, but that would still be "guessing" in which path the error actually occured. I would recommend that you store away the full path where the file error occured when it occurs. For example by expanding the tr_torrent struct with something like a pathWhereFileErrorOccured field.
rb07
Posts: 1400
Joined: Sun Aug 24, 2008 3:14 am

Re: Incorrect error message when failing to write to disk

Post by rb07 »

I think you are correct in your analysis. The solution is probably simpler than you think, its just a matter of figuring out if incompleteDir is being used, or not.

This forum is not the place to report errors like this, we have to use https://trac.transmissionbt.com/newticket (and you have to register to even view that page); and you'll probably get a response of "please use the latest (2.84) version" or "does the problem still exist in the latest...?", the answer is yes, just looking at the code, nothing has changed (maybe point that out in the report).

A sample code where the idea for a solution is used, libtransmission/torrent.c:

Code: Select all

  const char * dir = NULL;

  if (tor->incompleteDir == NULL)
    dir = tor->downloadDir;
  else if (!tr_torrentHasMetadata (tor)) /* no files to find */
    dir = tor->incompleteDir;
  else if (!tr_torrentFindFile2 (tor, 0, &dir, NULL, NULL))
    dir = tor->incompleteDir;
but this is probably overkill.
cfpp2p
Posts: 290
Joined: Sat Aug 08, 2009 3:14 pm

Re: Incorrect error message when failing to write to disk

Post by cfpp2p »

The error/bug can easily be reproduced, however if you look at transmission's message error log you should see the necessary information to easily track down the problem right away.

i.e.

Couldn't create "/_trs-part-dwnlds": Permission denied (utils.c:557)
Couldn't create "/_trs-part-dwnlds/True": Permission denied (fdlimit.c:366)
True tr_fdFileCheckout failed for "/_trs-part-dwnlds/True/file1": Permission denied (inout.c:145)
True Permission denied (/trs-dwnlds/True/file1) (torrent.c:533)
True Pausing (torrent.c:1994)
Couldn't create "/_trs-part-dwnlds": Permission denied (utils.c:557)
Couldn't create "/_trs-part-dwnlds/True": Permission denied (fdlimit.c:366)
True tr_fdFileCheckout failed for "/_trs-part-dwnlds/True/file2": Permission denied (inout.c:145)
Saved "/trs-str-Fix/.config/transmission-daemon/resume/True.23a7899bac14d255.resume" (bencode.c:1737)
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Re: Incorrect error message when failing to write to disk

Post by boise »

I had just posted this in the GTK+ Support forum (since I was told that this is not the right forum for Transmission-GTK problems) when I tested my back-reference to here and saw what you said about not posting bug reports in the forums :roll: :wink: So I registered on the trac site and created a ticket (don't have a tracking number for it since it hasn't been moderated yet) too. Seemed like last night would never end :)

Sure, there are different ways to fix the bug. However, I still think that the routine closest to the error should be the one that provides the information about it. In this case meaning that it should be the routine that fails to perform the fopen() on the specific file that has the responsibility to report the details of the error, including the file path and name. That is easy, so why let another routine a couple of calls away on the call stack attempt to guess the path where the error occurred?

Well, that's not my problem I guess :)

Oh, and about the "transmission's message error log": Where the heck do I find that? Maybe I'm just stupid, but I looked for it myself on my computer, googled the web, searched the forums, and browsed the documentation, and still couldn't find anything useful... :?
x190
Posts: 5094
Joined: Sun Nov 30, 2008 4:59 am

Re: Incorrect error message when failing to write to disk

Post by x190 »

In the readOrWritePiece() function in libtransmission/inout.c, when the call to the readOrWriteBytes() function returns an error code, tr_torrentSetLocalError() is called to register the error.

The problem lies in the parameters sent in that call to torrentSetLocalError(). The error code is correctly translated to a string with tr_strerror(err), but the value of the "path" variable is wrong.

The "path" variable is created on the line above (line 227 in v2.84) through a call to tr_buildPath(), and the bug is that the first argument in that call (the path to the file for which the error occurred) is incorrect. More specifically, the parameter is sent as tor->downloadDir, but it is far from certain that this is where the file error actually occurred. In my case, for example, the error really occurred in tor->incompleteDir.

Code: Select all

static int
readOrWritePiece (tr_torrent       * tor,
                  int                ioMode,
                  tr_piece_index_t   pieceIndex,
                  uint32_t           pieceOffset,
                  uint8_t          * buf,
                  size_t             buflen)
{
  int err = 0;
  tr_file_index_t fileIndex;
  uint64_t fileOffset;
  const tr_info * info = &tor->info;

  if (pieceIndex >= tor->info.pieceCount)
    return EINVAL;

  tr_ioFindFileLocation (tor, pieceIndex, pieceOffset,
                         &fileIndex, &fileOffset);

  while (buflen && !err)
    {
      const tr_file * file = &info->files[fileIndex];
      const uint64_t bytesThisPass = MIN (buflen, file->length - fileOffset);

      err = readOrWriteBytes (tor->session, tor, ioMode, fileIndex, fileOffset, buf, bytesThisPass);

      if ((err != 0) && (ioMode == TR_IO_WRITE) && (tor->error != TR_STAT_LOCAL_ERROR))
        {
          char * curdir = tr_torrentGetCurrentDir (tor);
          char * subpath = tr_sessionIsIncompleteFileNamingEnabled (tor->session)
                                   ? tr_torrentBuildPartial (tor, fileIndex)
                                   : tr_strdup (file->name);
          char * path = tr_buildPath (curdir, subpath, NULL);
          tr_torrentSetLocalError (tor, "%s (%s)", tr_strerror (err), path);

          tr_free (curdir);
          tr_free (subpath);
          tr_free (path);
        }

      buf += bytesThisPass;
      buflen -= bytesThisPass;
      fileIndex++;
      fileOffset = 0; 
    }

  return err;
}

boise or cfpp2p, please test. Code above may change, so check that you have the latest revision when testing.
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Re: Incorrect error message when failing to write to disk

Post by boise »

x190 wrote:boise or cfpp2p, please test. Code above may change, so check that you have the latest revision when testing.
I'm all new to Transmission (well, less than a months usage any way :) ) and have not done any work on it before, so it took me a while to set up the development environment after I saw this. Seems like the instructions for building need updating, both regarding which packages to install, and names of options (for enabling building of GTK).

Anyway, I checked out the trunk from the Subversion repository, pasted your updates into libtransmission/inout.c, built it, and tried it.

It works fine!

I tested it as before by dismounting the device that incompleteDir resides on, and opening a torrent for download. I still get an error of course, but now it is reported for the correct path.

I also tested what happens when incompleteDir is mounted, but downloadDir is not. What happens is (not surprisingly) that the download completes, but the completed file remains in incompleteDir (since it cannot be moved to a non-existing directory) though it is renamed by having the ".part" suffix removed.

Nothing wrong with that, but this happens silently. There is no warning (at least not that I noticed) about that the file could not be moved to downloadDir. And when I look at the properties for the torrent, all seems fine: State="Finished", Error="No errors", and Location indicates downloadDir (i.e. the directory where the file should be, rather than the directory where it really is).

This is definitely not an important bug, but since you are already in the process of fixing a related bug, I thought you might want to take a look at this too :wink:

Anyway, good work!
x190
Posts: 5094
Joined: Sun Nov 30, 2008 4:59 am

Re: Incorrect error message when failing to write to disk

Post by x190 »

It works fine!
Thanks. When your trac ticket gets posted, I'll propose this code as a patch.
There is no warning (at least not that I noticed) about that the file could not be moved to downloadDir.
You need to find your log. "var/log/transmission.log|sys.log|askUbuntu".

Code: Select all

(torrent.c)
static void
setLocation (void * vdata)
...
if (tr_moveFile (oldpath, newpath, &renamed))
                    {
                      err = true;
                      tr_logAddTorErr (tor, "error moving \"%s\" to \"%s\": %s",
                                       oldpath, newpath, tr_strerror (errno));
                    }
Location indicates downloadDir
Not sure how GTK gets that info. Let me know when you track it down. :wink:
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Re: Incorrect error message when failing to write to disk

Post by boise »

Almost 9 am after another sleepless night :(

I've been working on my JSON encode/decode module for PHP (no JSON module installed for PHP on the web server at work where I need it, and we are not allowed to download and install stuff there - so I just wrote my own :) ). It seems to work now, but I needed a break before I begin the more serious testing.

So:

I read somewhere that the goal is to moderate new tickets within a workday (I think it was), but I have no idea how long it will take in reality...

And yes, I do need to find the bloody log file, but as I said - I have failed miserably so far. I'm sure this is simple when you know how to do it, but I'm stuck.

There is no transmission.log in my entire file system, and I have also tried different derivatives of the name. The syslog contains nothing useful about Transmission. I cannot find anything useful with "find" or "grep" recursively from the root directory, and nothing that looks promising when just browsing the usual places.

I tried to follow the code for logging (e.g. in libtransmission/log.c), but it soon got too complicated to track. So I gave up and hacked the relevant routines to log everything, and hard-coded the destination to stdout. It's not pretty, but at least it worked.

I cut out the time-stamps (all within the same second anyway) and replaced the path and file names with shorter versions, but apart from that the log below shows the relevant log entries as they appeared in the log from the point where the torrent had finished downloading:

Code: Select all

[] XXX.mp3: State changed from "Incomplete" to "Complete"
[] Moving "XXX.mp3" location from currentDir "/home/bosse/Downloads" to "/MY_UNMOUNTED_DRIVE/TB/work"
[] Couldn't create "/MY_UNMOUNTED_DRIVE/TB": Permission denied
[] Found file #0: /home/bosse/Downloads/XXX.mp3
[] XXX.mp3: moving "/home/bosse/Downloads/XXX.mp3" to "/MY_UNMOUNTED_DRIVE/TB/work/XXX.mp3"
[] Couldn't create "/MY_UNMOUNTED_DRIVE/TB": Permission denied
[] XXX.mp3: error moving "/home/bosse/Downloads/XXX.mp3" to "/MY_UNMOUNTED_DRIVE/TB/work/XXX.mp3": Permission denied
[] XXX.mp3: Announcing to tracker
XXX.mp3 is the MP3 file that I chose randomly for testing. For this test incompleteDir is /home/bosse/Downloads/, and downloadDir is /MY_UNMOUNTED_DRIVE/TB/work/ .

The second to last log entry must be the one that the code snippet you posted generates. I don't think that the very last entry has anything to do with the problem - I just included it here to show what happened next.

So "the code" knows all about the problem - it just doesn't bother telling the user about it.

Need... to... sleep...
cfpp2p
Posts: 290
Joined: Sat Aug 08, 2009 3:14 pm

Re: Incorrect error message when failing to write to disk

Post by cfpp2p »

x190 wrote:... cfpp2p, please test. ...
Thanks x190 ! worked perfectly :)

For my piece temp fork I used a variation and moved everything into readOrWriteBytes() https://github.com/cfpp2p/transmission/ ... fe2a977ba2 but this was really just a personal preference.

I did quite a lot of testing.

boise wrote:There is no transmission.log in my entire file system...
with the daemon you can set the log file manually
transmission-daemon --logfile /path/to/log/file.log
Thanks for all of your research. :D
boise
Posts: 11
Joined: Tue Sep 09, 2014 2:48 am

Re: Incorrect error message when failing to write to disk

Post by boise »

x190 wrote:Not sure how GTK gets that info. Let me know when you track it down.
The the source code for the (torrent) Properties dialog is in details.c. The function refreshInfo() is responsible for filling in the information on the "Information" tab in the dialog, and in that function, the code for setting the "Location:" field (the di->destination_lb widget) can be found under the header comment "/* destination_lb */" (line 733 in the version I took from the SVN repository last night).

The problem here is similar to the bogus error message we discussed earlier, i.e. that the code doesn't care about where the torrent file actually is right now - it always gets the path with a call to tr_torrentGetDownloadDir(). In this case though, the file is still in the incompleteDir.

This is not really a bug in itself, though. It's more a case of misleading information: According to State and Error on the same dialog tab, the torrent is finished (which is true) and there were no errors (which is false). Given that information, one would assume that a field that is named "Location" really says where the file is right now. Maybe it should just be renamed "Target directory" ore something instead...

The real bug here is that the "Error" field (the di->error_lb widget) claims that there are no errors. What it should say is something like "Failed to move the finished torrent to the download directory. The file is still in <path to incomplete dir>.". This error should of course also be displayed on the status line for the torrent in the torrent list in the main window.

The code for setting the "Error:" field is in the same function as above, starting at the header comment "/* error_lb */" (line 972). I don't see any obvious bugs there, but I know too little about the exception handling in Transmission to be sure of anything...
cfppp2p wrote:with the daemon you can set the log file manually
Does that mean that I have to use the daemon to get a log?
cfpp2p
Posts: 290
Joined: Sat Aug 08, 2009 3:14 pm

Re: Incorrect error message when failing to write to disk

Post by cfpp2p »

boise wrote:Does that mean that I have to use the daemon to get a log?
No, you shouldn't have to.
Post Reply