POP3 server producing empty reports

[HandyGuySoftware]

From @peoman, related to Issue #105

Emails are being read & properly parsed, but extraction from database returning empty results, final report is empty.

Report:__init__()
options.getRcSection(report)
options.getRcSection(headings)
Report: reportOps=[{'sizedisplay': 'mega', 'reporttitle': 'Duplicati Backup Summary Report', 'border': 1, 'padding': 5, 'displayerrors': True, 'displaywarnings': True, 'displaymessages': False, 'sortby': 'source', 'style': 'bydest', 'showsizedisplay': True, 'titlebg': '#FFFFFF', 'subheadbg': '#D3D3D3', 'jobmessagebg': '#FFFFFF', 'jobwarningbg': '#FFFF00', 'joberrorbg': '#FF0000', 'repeatheaders': True, 'nobackupwarn': 0, 'nbwsubject': 'Backup Warning: #SOURCE##DELIMITER##DESTINATION# Backup Not Seen for #DAYS# Days', 'lastseensummary': 'bottom', 'lastseensummarytitle': 'Backup Sets Last Seen', 'lastseenlow': 5, 'lastseenlowcolor': '#FFFF00', 'lastseenmed': 10, 'lastseenmedcolor': '#FF9543', 'lastseenhighcolor': '#FF0000', 'truncatewarning': 25, 'truncateerror': 50, 'truncatemessage': 10, 'durationzeroes': False}]
Report: reportTits=[{'source': 'Source', 'destination': 'Destination', 'date': 'Date', 'time': 'Time', 'files': 'Files', 'filesplusminus': '+/-', 'size': 'Size', 'sizeplusminus': '+/-', 'errors': 'Errors', 'result': 'Result', 'jobmessages': 'Messages', 'jobwarnings': 'Warnings', 'joberrors': 'Errors', 'duration': 'Duration'}]
Report: rptColumns=[['source', 'destination', 'date', 'time', 'duration', 'files', 'filesplusminus', 'size', 'sizeplusminus', 'errors', 'result']]
extractReportData()
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[DELETE FROM report]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT source, destination, lastTimestamp, lastFileCount, lastFileSize FROM backupsets ORDER BY source, destination]
bkSetRows=[[('Batman', 'B2', 1546048860.0, 25245, 80569884296), ('Batman', 'Superman', 1546022183.0, 25245, 80569884296), ('Deanna', 'B2', 1546054017.0, 44162, 182119126695), ('Elk', 'B2', 1546083013.0, 2377, 160719826), ('Elk', 'Superman', 1546073109.0, 2377, 160719676), ('Gigantor', 'B2', 1512045357.0, 35, 21022839137), ('Jennifer', 'B2', 1545869278.0, 29926, 250961477166), ('Matthew', 'B2', 1545959793.0, 6097, 16136643362), ('Media', 'Gigantor', 1512138718.0, 1132, 266240186276), ('Media', 'Superman', 1546080127.0, 3461, 532182527920), ('Spiderman', 'B2', 1546075876.0, 49474, 265025048758), ('Spiderman', 'Gigantor', 1512111061.0, 224147, 889867349726), ('Spiderman', 'Superman', 1546065197.0, 49474, 265025048758), ('SpidermanArchive', 'Superman', 1545565523.0, 124883, 359259442138), ('WonderWoman', 'B2', 1546062254.0, 4393, 59440481910), ('WonderWoman', 'Gigantor', 1512113640.0, 3886, 22151919352), ('WonderWoman', 'Superman', 1546072644.0, 4393, 59440481910), ('Xena', 'B2', 1546029942.0, 12307, 221083283), ('Xena', 'Gigantor', 1512063928.0, 7534, 792997929), ('Xena', 'Superman', 1546019132.0, 12307, 221077279)]]
Src=[Batman] Dest=[B2] lastTimestamp=[1546048860.0] lastFileCount=[25245] lastFileSize=[80569884296]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Batman' AND destComp='B2'                 AND  endTimestamp > 1546048860.0 order by endTimestamp]
emailRows=[[]]
Src=[Batman] Dest=[Superman] lastTimestamp=[1546022183.0] lastFileCount=[25245] lastFileSize=[80569884296]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Batman' AND destComp='Superman'                 AND  endTimestamp > 1546022183.0 order by endTimestamp]
emailRows=[[]]
Src=[Deanna] Dest=[B2] lastTimestamp=[1546054017.0] lastFileCount=[44162] lastFileSize=[182119126695]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Deanna' AND destComp='B2'                 AND  endTimestamp > 1546054017.0 order by endTimestamp]
emailRows=[[]]
Src=[Elk] Dest=[B2] lastTimestamp=[1546083013.0] lastFileCount=[2377] lastFileSize=[160719826]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Elk' AND destComp='B2'                 AND  endTimestamp > 1546083013.0 order by endTimestamp]
emailRows=[[]]
Src=[Elk] Dest=[Superman] lastTimestamp=[1546073109.0] lastFileCount=[2377] lastFileSize=[160719676]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Elk' AND destComp='Superman'                 AND  endTimestamp > 1546073109.0 order by endTimestamp]
emailRows=[[]]
Src=[Gigantor] Dest=[B2] lastTimestamp=[1512045357.0] lastFileCount=[35] lastFileSize=[21022839137]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Gigantor' AND destComp='B2'                 AND  endTimestamp > 1512045357.0 order by endTimestamp]
emailRows=[[]]
Src=[Jennifer] Dest=[B2] lastTimestamp=[1545869278.0] lastFileCount=[29926] lastFileSize=[250961477166]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Jennifer' AND destComp='B2'                 AND  endTimestamp > 1545869278.0 order by endTimestamp]
emailRows=[[]]
Src=[Matthew] Dest=[B2] lastTimestamp=[1545959793.0] lastFileCount=[6097] lastFileSize=[16136643362]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Matthew' AND destComp='B2'                 AND  endTimestamp > 1545959793.0 order by endTimestamp]
emailRows=[[]]
Src=[Media] Dest=[Gigantor] lastTimestamp=[1512138718.0] lastFileCount=[1132] lastFileSize=[266240186276]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Media' AND destComp='Gigantor'                 AND  endTimestamp > 1512138718.0 order by endTimestamp]
emailRows=[[]]
Src=[Media] Dest=[Superman] lastTimestamp=[1546080127.0] lastFileCount=[3461] lastFileSize=[532182527920]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Media' AND destComp='Superman'                 AND  endTimestamp > 1546080127.0 order by endTimestamp]
emailRows=[[]]
Src=[Spiderman] Dest=[B2] lastTimestamp=[1546075876.0] lastFileCount=[49474] lastFileSize=[265025048758]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Spiderman' AND destComp='B2'                 AND  endTimestamp > 1546075876.0 order by endTimestamp]
emailRows=[[]]
Src=[Spiderman] Dest=[Gigantor] lastTimestamp=[1512111061.0] lastFileCount=[224147] lastFileSize=[889867349726]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Spiderman' AND destComp='Gigantor'                 AND  endTimestamp > 1512111061.0 order by endTimestamp]
emailRows=[[]]
Src=[Spiderman] Dest=[Superman] lastTimestamp=[1546065197.0] lastFileCount=[49474] lastFileSize=[265025048758]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Spiderman' AND destComp='Superman'                 AND  endTimestamp > 1546065197.0 order by endTimestamp]
emailRows=[[]]
Src=[SpidermanArchive] Dest=[Superman] lastTimestamp=[1545565523.0] lastFileCount=[124883] lastFileSize=[359259442138]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='SpidermanArchive' AND destComp='Superman'                 AND  endTimestamp > 1545565523.0 order by endTimestamp]
emailRows=[[]]
Src=[WonderWoman] Dest=[B2] lastTimestamp=[1546062254.0] lastFileCount=[4393] lastFileSize=[59440481910]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='WonderWoman' AND destComp='B2'                 AND  endTimestamp > 1546062254.0 order by endTimestamp]
emailRows=[[]]
Src=[WonderWoman] Dest=[Gigantor] lastTimestamp=[1512113640.0] lastFileCount=[3886] lastFileSize=[22151919352]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='WonderWoman' AND destComp='Gigantor'                 AND  endTimestamp > 1512113640.0 order by endTimestamp]
emailRows=[[]]
Src=[WonderWoman] Dest=[Superman] lastTimestamp=[1546072644.0] lastFileCount=[4393] lastFileSize=[59440481910]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='WonderWoman' AND destComp='Superman'                 AND  endTimestamp > 1546072644.0 order by endTimestamp]
emailRows=[[]]
Src=[Xena] Dest=[B2] lastTimestamp=[1546029942.0] lastFileCount=[12307] lastFileSize=[221083283]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Xena' AND destComp='B2'                 AND  endTimestamp > 1546029942.0 order by endTimestamp]
emailRows=[[]]
Src=[Xena] Dest=[Gigantor] lastTimestamp=[1512063928.0] lastFileCount=[7534] lastFileSize=[792997929]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Xena' AND destComp='Gigantor'                 AND  endTimestamp > 1512063928.0 order by endTimestamp]
emailRows=[[]]
Src=[Xena] Dest=[Superman] lastTimestamp=[1546019132.0] lastFileCount=[12307] lastFileSize=[221077279]
Database.execSqlStmt(): Executing SQL command.
SQL stmt=[SELECT endTimestamp, beginTimeStamp, duration, examinedFiles, sizeOfExaminedFiles, addedFiles, deletedFiles, modifiedFiles,                 filesWithError, parsedResult, warnings, errors, messages FROM emails WHERE sourceComp='Xena' AND destComp='Superman'                 AND  endTimestamp > 1546019132.0 order by endTimestamp]
emailRows=[[]]
rpt_bydest()

dupReport.log

[HandyGuySoftware]

This appears to be an issue with the way POP3 is managed on the server. POP3 will mark emails as read once it is downloaded. The next time you try to download those messages will not be re-downloaded.

To fix, you must use the "Leave email on server" option in your email client. This will leave the emails on the server and make them available for future use.

Also, if using Gmail, you must alter the email server username to recent:username@gmail.com. This tells Gmail to download the most recent 30 days of email. Otherwise, it will start from the oldest email in your inbox.

[peoman69]

I can confirm that the "extractHeaders" issue is fixed with Issue_105 release. But still, the emails produced are empty, although slightly different. It now has the line below: "No new activity. Last activity on 01/01/1970 at 02:00:00 (17917 days ago)"

“Leave messages on the server” is already checked to my Outlook. I've even tried to mark as unread the mails from the webmail.

Probably, it has something to do with this:

Next Message: Date=[Mon, 21 Jan 2019 13:06:36 +0200] Subject=[Duplicati Backup report for] Message-Id=[<UCHLA02SJ6U4.1T0UJU1MBUET@COMPUTERNAME>]
srcregex=[\w*\-]  destRegex=[\-\w*]
SrcDestDelimeter [-] not found in subject line. Skipping message.
dremail.processNextMessage()

I don't know if it's a misconfiguration from me or a thing with the POP3.

I've attached the latest log file (verbose=3) dupReport.log.zip

[HandyGuySoftware]

1/1/1970 is the earliest date that can be recorded on a system. This message means that dR has never recorded a backup for a particular backup job before.

The log shows that dR is not finding the proper pattern in the subject. This is shown by Subject=[Duplicati Backup report for Outlook] and subject=[Duplicati Backup report for]

How do you have your Duplicati backup jobs named? For dR to work properly, you backup jobs must be named in the form:

<source><delimiter><destination>

for example:

Outlook-BackupServer

where \<source> is "Outlook", \<delimiter> is "-", and \<destination> is "BackupServer"

See the section on Source/Destination pairs in the docs for a better explanation of how this works. dR is skipping these mesages because the subject lines don't match the standard pattern. As a result, it doesn't see these as valid backup emails.

[peoman69]

Sorry for that. I knew i forgot something!

I changed "send-mail-subject" to:

Duplicati %OPERATIONNAME% report for %backup-name%-Test

and now it seems to find the new e-mails and the dupReport.db has a new entry in "backupsets" table!

But now a new error occurs:

C:\dupReport>python dupReport.py -v3
Traceback (most recent call last):
  File "dupReport.py", line 234, in <module>
    nxtMsg = globs.inServer.processNextMessage()
  File "C:\dupReport\dremail.py", line 414, in processNextMessage
    globs.log.write(3, 'Message Body=[{}]'.format(msgBody))
  File "C:\dupReport\log.py", line 88, in write
    logTarget.write(msg)
  File "C:\Users\%USERNAME%\AppData\Local\Programs\Python\Python37\lib\encodings\cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
UnicodeEncodeError: 'charmap' codec can't encode characters in position 538-539: character maps to <undefined>

I've attached the latest log file (verbose=3) dupReport.log

[HandyGuySoftware]

I uploaded a small patch to the Issue_105 code. Not sure if this is a final fix, but let's see if it works.

[peoman69]

Sorry...

C:\dupReport3>python dupReport.py -v3
Traceback (most recent call last):
  File "dupReport.py", line 234, in <module>
    nxtMsg = globs.inServer.processNextMessage()
  File "C:\dupReport3\dremail.py", line 431, in processNextMessage
    dateParts['endTimestamp'] = self.parenOrRaw(statusParts['endTimeStr'], df = dt, tf = tm, tz = msgParts['timezone'])
  File "C:\dupReport3\dremail.py", line 229, in parenOrRaw
    globs.log.write(1,'dremail.parenOrRaw({}, {}, {}, {})'.format(val, df, tf, tz))
  File "C:\dupReport3\log.py", line 88, in write
    logTarget.write(msg)
  File "C:\Users\%USERNAME%\AppData\Local\Programs\Python\Python37\lib\encodings\cp1252.py", line 19, in encode
    return codecs.charmap_encode(input,self.errors,encoding_table)[0]
UnicodeEncodeError: 'charmap' codec can't encode characters in position 37-38: character maps to <undefined>

I've attached the latest log file (verbose=3) dupReport.log

[HandyGuySoftware]

I think I know what the issue is, just trying to find the best place to fix it. Just made another patch & uploaded to Issue_105 branch. Have a try and see if it works. Fingers crossed!

[peoman69]

And now it works! Thank you so much.

[HandyGuySoftware]

Good to hear it's working. I'll move this over to pre_prod and let it test out for a while until I fully release it. Watch the Duplicati forum page for announcements on when that happens.

[HandyGuySoftware]

Fixed in 2.2.5