logging is incomplete and inconsistent in the web UI back-end

[tmetro]

When adding a torrent from a URL, you might see an error logged like:

[ERROR   ] 16:56:57 json_api:661 Error occured downloading torrent from https://btguard.com/broken-test.torrent
[ERROR   ] 16:56:57 json_api:662 Reason: 404 Not Found

or like:

[WARNING ] 16:06:52 common:72 Unable to open /tmp/delugeweb-s3EDsB/bad-url.torrent: not a valid bencoded string
[ERROR   ] 16:06:52 json_api:700 not a valid bencoded string
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/deluge/ui/web/json_api.py", line 697, in get_torrent_info
    torrent_info = uicommon.TorrentInfo(filename.strip(), 2)
  File "/usr/lib/python2.7/dist-packages/deluge/ui/common.py", line 73, in __init__
    raise e
Exception: not a valid bencoded string

In the first case, it appears the failure occurs during the download_torrent_from_url() API call, while in the latter case the failure occurs in the add_torrents() call (when the contents of the previously retrieved file are discovered to not be a torrent).

In neither case is the relevant failing API logged.

In neither case are successful API calls logged, despite the service running with INFO logging level (-L info).

This makes it difficult to troubleshoot failures.

[Cas]

I am not sure what more information you require from the errors. A 404 error indicates a broken HTTP link and not a valid bencoded string usually indicates a corrupt torrent file.

[tmetro]

Replying to Cas:

I am not sure what more information you require from the errors.

Lets see if I can clarify.

For errors:

The log message should include the relevant failing API method.

For example:

[ERROR   ] 16:56:57 json_api:661 download_torrent_from_url: https://btguard.com/broken-test.torrent: Error occured downloading torrent: 404 Not Found

When the log level is INFO:

There should be log entries marking the entry into API methods, along with the arguments (to the extent that is practical).

For example:

[INFO    ] 23:50:01 json_api:773 download_torrent_from_url called with options {url: 'https://btguard.com/broken-test.torrent', ...}

A 404 error indicates a broken HTTP link...

I said "This makes it difficult to troubleshoot failures" because I was testing a 3rd party client (only testing; not one I wrote) that uses your AJAX API, and was attempting to exercise its error handing with falling URLs, and it wasn't until repeated tests that I was able to determine that there were two API calls involved (first download_torrent_from_url(), then add_torrents()) and that some of my test URLs weren't 404ing as expected, but instead passing the first API call, because the sites were returning HTML with a success code instead of a 404.

The general expectation is that something as significant as an AJAX method call in a web service back-end, whose whole purpose is to provide said AJAX API, will log those calls when at an INFO logging level.

(Also on the topic of logging, it would be nice to see ISO datestamps instead of just timestamps, like "22:08:06".)

not a valid bencoded string usually indicates a corrupt torrent file.

Seems like there should be a more explicit validity test for a torrent file, and better error trapping, rather than a stack trace. But this is a side issue unrelated to this ticket.

[Cas]

Logging across the entire Deluge application can be patchy and the json api does seem particularly bad for this.

I should point out that there is already a line number and the log always shows the line number which can be correlated with source code and thus the method if required. The inclusion of the method name could be done application wide, it might make log entries very long or duplicate the essence of the existing log message but certainly can consider it.

ISO datestamps instead of just timestamps

I think the reason for not using the date is to keep log lines shorter but ISO format could also be considered.

When the log level is INFO There should be log entries marking the entry into API methods, along with the arguments (to the extent that is practical).

There is a ticket to add more info logging lines across the Deluge code but has to be done carefully to avoid any performance hit.

Seems like there should be a more explicit validity test for a torrent file, and better error trapping, rather than a stack trace. But this is a side issue unrelated to this ticket.

The latter stack trace is actually a log of the trace so it is handled correctly but it probably does not require this level of logging in code and could be modified to be a log error message. It should be noted however that this trace provides you with the very information you were asking for, the originating method which was get_torrent_info not add_torrents. I am not sure what else should be done here.

[tmetro]

Thanks for the reply and your consideration.

...the log always shows the line number which can be correlated with source code...

I see, which is better than nothing. I realize that makes for an easy way to create a generic logging routine, but I should still be able to get the gist of what is going on without digging into the source. Postfix, for example, doesn't spit out code line numbers for each logged message. (Source is available, so it could.) The messages are self-contained and describe the major processing action that is taking place.

I wasn't sure that "json_api:661" was "module:line-nuber" or if you were emulating syslog and displaying service and PID. (On closer examination, they clearly fit what you describe.) In the interest of shorter log messages, if the method names are added, the "module:line-nuber" part should be removed. (Though it could still be useful to have in a generic error handler for otherwise unhandled exceptions, however, I suspect you'll use a stack trace for that, which already includes such information.)

The inclusion of the method name could be done application wide...

If it makes sense elsewhere. It may not. Per the Postfix example above, it doesn't log internal method (function) names. In a typical service, they may make no sense to anyone not already intimately familiar with the code internals.

I suggested it for the AJAX service because it is naturally organized around a public API with method names that a client developer is going to be well familiar with. These method names clearly indicate the major (high-level) activity that was in progress when the log message was issued.

...has to be done carefully to avoid any performance hit.

If I have INFO level logging enabled, I'm OK with some performance hit.

...it might make log entries very long... ...not using the date is to keep log lines shorter...

Sure. But if you're going to keep them shoty, then you want them to be under 80 characters, and that is really constraining. Otherwise anything under a few hundred characters is fine.

It's generally easier to use existing tools to process logs with long lines than it is to deal with logs that split messages across multiple lines.

The latter stack trace is actually a log of the trace so it is handled correctly...

A trace says to me, "hey, we didn't completely crash, but something we didn't plan for happened, so here are the details so you can figure it out."

My point was that you're going to see invalid torrent files as a common occurrence. It should be a fully handled condition with a descriptive error message returned that can be appropriately handled (and translated) by the client.

(On a side note, the email I received for this ticked used an HTTPS URL: ​https://dev.deluge-torrent.org/ticket/2339#comment:3 which causes my browser (with extra security checks enabled) to report an "OCSP server has refused this request as unauthorized" error. Maybe you aren't really setup for HTTPS and your Trac should be adjusted to embed HTTP URLs in the emails.)

[Cas]

Milestone renamed