Download of attachement simply stopps

[baxerus]

The download of attachments simply stops with the first "real" attachement (I use filter (! seen) and filter out the files I want later), that is a PNG image.

Debug shows: DEBUG:download:Save file /var/attachements/temp.file and nothing after that.

BTW: cool tool!

[izderadicka]

Can you provide bit more details?
Full command line Which IMAP server? So file /var/attachements/temp.file is saved? If you are using !seen are you sure that emails have not been opened before by other email client?

[baxerus]

The IMAP server is dovecot 2.2.34 (874deae)

The full command line is (I added --debug for the test and changed (! seen) to (seen) to reprocess the testmail repeatedly, without sending it again and agian):

detach.py \
    --host ${HOST} \
    --user ${USER} \
    --password ${PASSWORD} \
    --file-name '/var/attachements/temp.file' \
    --command '/processing.sh "{file_name}" "{from}" "{to}" "{date}" "{name}" "{subject}"' \
    --insecure-ssl \
    --seen \
--debug \
    -v \
    '(seen)'

It is a special email address that is only opened by imap_detach, so no other client could has opened something before. Also it isn't the problem, that the email isn't opened in the DEBUG log I can see, that the first parts of the mail plain text and html are processed and given to the command (I modified my processing.sh for testing to save all tempfiles to the great $(date +%Y%m%d-%H%M%S-%N) filename, so it is receiving and working, because the first two parts (section 1 and section 2.1) are saved as files). But the third part (section 2.2) what is an PNG image is saved (DEBUG:download:Save file /var/attachements/temp.file) but the command is never executed after that (no further log). I looked at the temp.file and compared it to the original with diff. The are exactly the same. So the file was already completely saved to disk.

Can I do something more to find the problem? Is there a "more debug" option? Should I add print() statements into the code (but than a hint, where to do it would be great)?

[izderadicka]

This is the code that saves file (download.py line 148):

    def run(self, part):
        if self._file:
            with open(self._file, 'wb') as f:
                f.write(part)
            log.debug("Save file %s", self._file)
        if self._command:
            self._timer.start()
            input_pipe=subprocess.PIPE if not self._file else None
            self._process = subprocess.Popen(self._command, shell=True, 
                            stdin=input_pipe, stderr=subprocess.PIPE, stdout= subprocess.PIPE, 
                            close_fds=True)
            self._stdout, self._stderr =self._process.communicate(None if self._file else part ) 
            self._timer.cancel()
            if self._killed:
                msg= 'Command %s timeouted'% (self._command,)
                log.error(msg)
                raise CommandRunner.Terminated('msg')
            if self._process.returncode != 0:
                msg= 'Command %s failed  with code %d'% (self._command, self._process.returncode)
                log.error(msg)
                raise CommandRunner.Error(msg)
            if self._delete and self._file and os.access(self._file, os.W_OK):
                os.remove(self._file)

As you can see here part is saved into file - if just opens the file and writes to it. If any problem occurs it should rise exception. Only idea I have is that part is empty here.

run is called from (download.py line 51):

def download_part(msgid, part_info, msg_info, filename, command=None, client=None, 
                  delete_file=False, max_time=60):

    part_id=('BODY[%s]'%part_info.section).encode('ascii')

    try:
        cmd=CommandRunner(command, filename, msg_info, delete_file, max_time)
    except ValueError as e:
        log.exception("Cannot download message: %s",e)
        return

    part=client.fetch(msgid, [part_id])
    part=part[msgid][part_id]
    part=decode_part(part, part_info.encoding)
    if lower_safe(part_info.type) == 'text':
        charset=lower_safe(part_info.params.get('charset') )
        if charset:
            part=reencode_charset(part, charset)

    try:
        cmd.run(part)
    except CommandRunner.Error as e:
        pass
    if command:
        log.debug('Command stdout:\n%s\nCommand stderr:\n%s\n', cmd.stdout, cmd.stderr)

I think easiest would be to debug it with break point in the above function - problem might be decode_part? See what part is fetched from server and what happens with it later. Also you can send parts to command rather then to file - you can try wc -c to see how many bytes each part have?

[baxerus]

Sorry for the late reply, will look into it in detail this week.

But some first answers:

Only idea I have is that part is empty here.

The file is actually saved and not empty. I made a diff to the original file and it is identical, so nothing left at the end or so. Also the log message from log.debug("Save file %s", self._file) is in the logging. But nothing happens after this.

I will add another debug message so the what the content of self._command is. Perhaps there is something with it? But than, even if self._command would be empty, the next section of the mail should be processed, isn't it?

What does self._timer.start() and self._timer.cancel() do? Only measuring? Or forcing a maximum executing time in some way? Could there be a problem in the timer function?

[izderadicka]

_timer is controlling maximum execution time of external command (default is 60 seconds, after which command process is killed). It does not however influence part download into file.

[baxerus]

Okay, than most likely also self.timer is never reached, because than after maximum 60sec the next part of the email should be processed, isn't it?

Will check that with log.debug all over the place 😉

[baxerus]

Okay. I found the issue. It was a problem with my script that was called. There was an infinite loop in it. Not good!

But the _timer didn't work either to stop the subprocess ☹️. I had it running for much more than 60 seconds (nearly a week).