execute plugin fails intermittently

Suggest, post, or discuss plugins for Deluge
voltaicsca
New User
New User
Posts: 8
Joined: Sat Dec 17, 2011 3:50 am

execute plugin fails intermittently

Post by voltaicsca »

sometimes the execute plugin fails to execute with the following error in the log file:

Code: Select all

[DEBUG   ] 04:35:56 alertmanager:123 torrent_finished_alert: << torrent name >> torrent finished downloading
[DEBUG   ] 04:35:56 alertmanager:123 state_changed_alert: << torrent name >>: state changed to: finished
[DEBUG   ] 04:35:56 alertmanager:123 state_changed_alert: << torrent name >>: state changed to: seeding
[DEBUG   ] 04:35:56 alertmanager:123 tracker_announce_alert: << torrent name >> (udp://tracker.openbittorrent.com:80) sending announce (completed)
[DEBUG   ] 04:35:56 torrentmanager:869 on_alert_torrent_finished
[DEBUG   ] 04:35:56 torrentmanager:875 << torrent id >> is finished..
[DEBUG   ] 04:35:56 rpcserver:466 intevents: {4426: ['TorrentRemovedEvent', 'PluginEnabledEvent', 'TorrentAddedEvent', 'PluginDisabledEvent', 'TorrentStateChangedEvent', 'ConfigValueChangedEvent']}
[DEBUG   ] 04:35:56 core:111 [execute] Running commands for complete
[DEBUG   ] 04:35:56 core:127 [execute] running /home/deluge/complete.sh
[ERROR   ] 04:35:56 eventmanager:59 Event handler TorrentFinishedEvent failed in <function event_handler at 0x1f976e0>
The script that is supposed to run when a torrent completes never gets touched. ie, the failure occurs before ever actually invoking the script.
Also, I have tested my script, and it works always when invoked from the command line, and sometimes when run from deluge.

I'm running deluge 1.3.5 on ubuntu server 10.04 LTS

anyone have any ideas?

PS, I don't think it's relevant, but here's the script i'm running:

Code: Select all

#!/bin/bash

torrentid="$1"
torrentname="$2"
torrentpath="$3"

localpath="/home/deluge/"
remotepath="/path/to/remote/files/"

scpresume="rsync --partial --progress --inplace --rsh=ssh"

retries=0
result=1

torrentfullpath="$torrentpath/$torrentname"
echo "\"${torrentfullpath}\""
#remove the /home/deluge part of the full path.
torrentdest=${torrentfullpath#$localpath}
#now add the remote path to the torrentdest
torrentdest="${remotepath}${torrentdest}"
#get the directory name only for the destination
torrentdest=`dirname "${torrentdest}"`
#escape spaces.
torrentdest="${torrentdest// /\ }"
#torrentfullpath="${torrentfullpath// /asdfasdf}"

echo "log for $torrentname, $torrentid" >> /home/deluge/lastxfer.txt

starttime=`date +%s`
date 
echo starttime: $starttime


until (( retries>60 || result==0 ))
do
        #wait a little longer each time.
        sleep $((retries/2))m
        (( retries += 1 ))
        echo "try #${retries}" >> /home/deluge/lastxfer.txt
        echo $scpresume -r "'${torrentfullpath}'" user@sshserver:"${torrentdest}/" >> /home/deluge/lastxfer.$
        eval $scpresume -r "\"$torrentfullpath\"" user@sshserver:"${torrentdest}/"
        result=$?
done


if (( result != 0 ))
        then
        echo "scp never completed sucesssfully" >> /home/deluge/lastxfer.txt
else
        endtime=`date +%s`
        date
        echo entime: $endtime

        totaltime=$((endtime-starttime+1))
        echo totaltime: $totaltime
        size=`du -s "$torrentfullpath"`
        set -- $size
        size=$1
        echo "removing $torrentname" >> /home/deluge/lastxfer.txt
        echo $torrentid
        echo $? >> /home/deluge/lastxfer.txt
        avgspeed=$((size/totaltime))
        echo -e "Subject: $torrentname finished\nTo: email@addres.com\nDate: `date`\nFrom: email@address.com\n\nfile $
        fi
 
echo "" >> /home/deluge/lastxfer.txt
johnnyg
Top Bloke
Top Bloke
Posts: 1522
Joined: Sun Oct 28, 2007 4:00 am
Location: Sydney, Australia

Re: execute plugin fails intermittently

Post by johnnyg »

Hmm that doesn't give us much info to go off.
Something is going wrong when trying to run the script (which is weird).

Is that the only script that's running?
As of Deluge 1.3.4 scripts are run asynchronously (i.e. deluge doesn't block when running scripts), so it's possible to have two scripts running at the same time.

If your script produces an error then that should get caught though (and it will print so).
The only thing that doesn't get caught at the moment is if your script raises a signal (which your script doesn't do unless it's somehow being killed).

How do you know it's not being touched at all? By inspecting your lastxfer.txt file?
Your echos won't get printed unless your script exits with a non-zero status code.
You could modify your script to do so however I suspect that won't help as it's not getting to the part where it can print things.

The best way to debug this would be to modify the source to print what the exception was (+ a traceback), however I'm guessing you installed Deluge from the PPA?
voltaicsca
New User
New User
Posts: 8
Joined: Sat Dec 17, 2011 3:50 am

Re: execute plugin fails intermittently

Post by voltaicsca »

I realize that is pretty scant information to go on.
It is the only script that is running when it is invoked.
I did install from the PPA, but I don't have any qualms about rolling my own with more debugging info. Also, deluge is written in Python, isn't it? shouldn't I be able to modify my source in-place on the running system?
I'll give that a try, and see what I can find out. I'm guessing from the log file that the source file to modify would be eventmanager, somewhere around line 59?
johnnyg
Top Bloke
Top Bloke
Posts: 1522
Joined: Sun Oct 28, 2007 4:00 am
Location: Sydney, Australia

Re: execute plugin fails intermittently

Post by johnnyg »

Yes Deluge is written in Python so you could do that.

Obviously it's slightly easier to patch if you've installed from source.

Yes you would need to modify eventmanager.py.

Simplest way to debug would be to log the exception:

Code: Select all

diff --git a/deluge/core/eventmanager.py b/deluge/core/eventmanager.py
index c663491..424f111 100644
--- a/deluge/core/eventmanager.py
+++ b/deluge/core/eventmanager.py
@@ -55,8 +55,9 @@ def emit(self, event):
                 #log.debug("Running handler %s for event %s with args: %s", event.name, handler, event.args)
                 try:
                     handler(*event.args)
-                except:
+                except Exception, e:
                     log.error("Event handler %s failed in %s", event.name, handler)
+                    log.exception(e)
 
     def register_event_handler(self, event, handler):
         """
voltaicsca
New User
New User
Posts: 8
Joined: Sat Dec 17, 2011 3:50 am

Re: execute plugin fails intermittently

Post by voltaicsca »

Awesome! Very helpful. Thanks!

I'll give that a try and report back.
voltaicsca
New User
New User
Posts: 8
Joined: Sat Dec 17, 2011 3:50 am

Re: execute plugin fails intermittently

Post by voltaicsca »

I haven't forgotten about this, but since I added that code to the eventmanager.py file, the thing hasn't failed once, which is odd since it used to fail about once a week.

I keep hoping it will fail so I can have some concrete idea of what is actually happening, rather than having some mysterious "fix" that resulted from changing something unrelated in the code... Anyway, I'm still watching.
terrukallan

Re: execute plugin fails intermittently

Post by terrukallan »

I was experiencing what is presumably the same problem, but unlike voltaicsca I've been able to reproduce it consistently. It's caused by unicode characters in the torrent name.

Here's the stack trace:

Code: Select all

[ERROR   ] 19:01:52 eventmanager:60 Arguments contain a non-string value
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/deluge/core/eventmanager.py", line 57, in emit
    handler(*event.args)
  File "/usr/lib/python2.7/dist-packages/deluge/plugins/Execute-1.2.egg/execute/core.py", line 90, in event_handler
    self.execute_commands(torrent_id, event)
  File "/usr/lib/python2.7/dist-packages/deluge/plugins/Execute-1.2.egg/execute/core.py", line 130, in execute_commands
    d = getProcessOutputAndValue(command, (torrent_id, torrent_name, save_path), env=os.environ)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/utils.py", line 169, in getProcessOutputAndValue
    reactor)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/utils.py", line 25, in _callProtocolWithDeferred
    reactor.spawnProcess(p, executable, (executable,)+tuple(args), env, path)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/posixbase.py", line 328, in spawnProcess
    args, env = self._checkProcessArgs(args, env)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/base.py", line 886, in _checkProcessArgs
    raise TypeError("Arguments contain a non-string value")
TypeError: Arguments contain a non-string value
Twisted (getProcessOutputAndValue) is throwing the TypeError because it's attempting to turn any arguments of type unicode to strings by using the python system encoding (sys.getdefaultencoding()). On my system, this is ascii by default so any unicode strings fail to decode and throw the error.

Just as a quick hack to get things working for me, I've made the following addition in execute/core.py:

Code: Select all

        # Go through and execute all the commands
        for command in self.config["commands"]:
            if command[EXECUTE_EVENT] == event:
                command = os.path.expandvars(command[EXECUTE_COMMAND])
                command = os.path.expanduser(command)
                log.debug("[execute] running %s", command)
+               if isinstance(torrent_name, unicode):
+                   torrent_name = torrent_name.encode('utf-8')
                d = getProcessOutputAndValue(command, (torrent_id, torrent_name, save_path), env=os.environ)
                d.addCallback(log_error, command)
With this in place, the previously failing torrents are getting passed to my execute scripts.

Edit: forgot to mention that this is 1.3.5 on Ubuntu 12.04
chimpy
New User
New User
Posts: 6
Joined: Sun Mar 11, 2012 4:06 pm

Re: execute plugin fails intermittently

Post by chimpy »

This error is also causing my script to fail intermittently too. Trying out terrukalian's solution, but it's not working :(

This is indeed the file I need to edit, right? /usr/share/pyshared/deluge/plugins/Execute-1.2.egg/execute/core.py

Thanks!
chimpy
New User
New User
Posts: 6
Joined: Sun Mar 11, 2012 4:06 pm

Re: execute plugin fails intermittently

Post by chimpy »

Just restarted Deluge and the fix works magnificently! Thank you so much terrukalian + others! :)

That change should probably be committed into 1.3.6, no?
Cas
Top Bloke
Top Bloke
Posts: 3679
Joined: Mon Dec 07, 2009 6:04 am
Location: Scotland

Re: execute plugin fails intermittently

Post by Cas »

If you create a ticket and mark it for 1.3.6 milestone then it will be dealt with.
Post Reply