No mail report from scheduled jobs even though it works from send-mail/backup through web command line!


#1

Hi there,

I do not receive mail reports from my scheduled backup jobs. Just upgraded to version 2.0.3.12_canary_2018-10-23 to see if it resolved anything, but no. The strange thing is that when I test the configuration in command line (both “send-mail” and “backup”), it all works and I receive the mail report! It runs on a QNAP NAS. App compilation is from qnapclub.eu.

I have no clue what the difference is between the two methods and I need help, please.

My static configuration:

--compression-module="zip"
--compression-extension-file="/share/CACHEDEV1_DATA/.qpkg/Duplicati/Duplicati/default_compressed_extensions.txt"
--debug-retry-errors=true
--send-mail-any-operation=true
--send-mail-body="%RESULT%"
--send-mail-from="Duplicati Backup <...@gmail.com>"
--send-mail-level="all"
--send-mail-subject="%PARSEDRESULT% - Duplicati %OPERATIONNAME% report"
--send-mail-to="Me <...@gmail.com>"
--send-mail-url="smtp://smtp.gmail.com:587/?starttls=when-available"
--send-mail-username="...@gmail.com"
--send-mail-password="..."
--console-log-level=Verbose

My command line configuration:

--compression-module=zip
--compression-extension-file="/share/CACHEDEV1_DATA/.qpkg/Duplicati/Duplicati/default_compressed_extensions.txt"
--debug-retry-errors=true
--send-mail-any-operation=true
--send-mail-body="%RESULT%"
--send-mail-from="Duplicati Backup <...@gmail.com>"
--send-mail-level="all"
--send-mail-subject="%PARSEDRESULT% - Duplicati %OPERATIONNAME% report"
--send-mail-to="Me <...@gmail.com>"
--send-mail-url="smtp://smtp.gmail.com:587/?starttls=when-available"
--send-mail-username="...@gmail.com"
--send-mail-password="..."
--console-log-level=Verbose
--full-result=true
--backup-name=Backup
--dbpath=/share/CACHEDEV1_DATA/.qpkg/Duplicati/.config/Duplicati/72857877698674868879.sqlite
--encryption-module=aes
--dblock-size=50mb
--passphrase=...
--retention-policy=1W:1D,4W:1W,12M:1M
--disable-module=console-password-input

My command line log from a successfully execution of send-mail:

The operation SendMail has started
Hele SMTP-kommunikationen: Connected to smtp://smtp.gmail.com:587/?starttls=when-available
S: 220 smtp.gmail.com ESMTP d64-v6sm175545edd.29 - gsmtp
C: EHLO [<IP>]
S: 250-smtp.gmail.com at your service, [...]
S: 250-SIZE 35882577
S: 250-8BITMIME
S: 250-STARTTLS
S: 250-ENHANCEDSTATUSCODES
S: 250-PIPELINING
S: 250-CHUNKING
S: 250 SMTPUTF8
C: STARTTLS
S: 220 2.0.0 Ready to start TLS
C: EHLO [<IP>]
S: 250-smtp.gmail.com at your service, [...]
S: 250-SIZE 35882577
S: 250-8BITMIME
S: 250-AUTH LOGIN PLAIN XOAUTH2 PLAIN-CLIENTTOKEN OAUTHBEARER XOAUTH
S: 250-ENHANCEDSTATUSCODES
S: 250-PIPELINING
S: 250-CHUNKING
S: 250 SMTPUTF8
C: AUTH XOAUTH2 ...
S: 334 ...
C: AUTH PLAIN ...
S: 535-5.7.8 Username and Password not accepted. Learn more at
S: 535 5.7.8  https://support.google.com/mail/?p=BadCredentials d64-v6sm175545edd.29 - gsmtp
C: AUTH LOGIN
S: 334 ...
C: ...
S: 334 ...
C: ...
S: 235 2.7.0 Accepted
C: MAIL FROM:<...@gmail.com>
C: RCPT TO:<...@gmail.com>
S: 250 2.1.0 OK d64-v6sm175545edd.29 - gsmtp
S: 250 2.1.5 OK d64-v6sm175545edd.29 - gsmtp
C: DATA
S: 354  Go ahead d64-v6sm175545edd.29 - gsmtp
C: From: Duplicati Backup <...@gmail.com>
C: Date: Sun, 28 Oct 2018 11:53:19 +0100
C: Subject: Success - Duplicati SendMail report
C: Message-Id: <...>
C: To: Me <...@gmail.com>
C: MIME-Version: 1.0
C: Content-Type: text/plain; charset=utf-8
C: Content-Transfer-Encoding: 7bit
C: 
C: MainOperation: SendMail
C: Lines: []
C: ParsedResult: Success
C: Version: 2.0.3.12 (2.0.3.12_canary_2018-10-23)
C: EndTime: 10/28/2018 11:53:19 AM (1540723999)
C: BeginTime: 10/28/2018 11:53:19 AM (1540723999)
C: Duration: 00:00:00.0402790
C: 
C: .
S: 250 2.0.0 OK 1540724000 d64-v6sm175545edd.29 - gsmtp
C: QUIT
S: 221 2.0.0 closing connection d64-v6sm175545edd.29 - gsmtp

Email sendt med succes ved hjælp af server: smtp://smtp.gmail.com:587/?starttls=when-available
Email sendt med succes ved hjælp af server: smtp://smtp.gmail.com:587/?starttls=when-available
Return code: 0

I wonder why the log at first fail login and afterwards succeed…

A backup log from a manual job execution:

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 119467
OpenedFiles: 0
AddedFiles: 0
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 195236679400
SizeOfOpenedFiles: 0
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults:
    DeletedSets: []
    Dryrun: False
    MainOperation: Delete
    CompactResults: null
    ParsedResult: Success
    Version: 2.0.3.12 (2.0.3.12_canary_2018-10-23)
    EndTime: 10/28/2018 12:57:10 PM (1540727830)
    BeginTime: 10/28/2018 12:56:45 PM (1540727805)
    Duration: 00:00:25.3684180
    Messages: [
        2018-10-28 12:48:43 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-10-28 12:52:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-10-28 12:53:31 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6,61 KB),
        2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
        2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
    ]
    Warnings: []
    Errors: []
    BackendStatistics:
        RemoteCalls: 5
        BytesUploaded: 0
        BytesDownloaded: 63174839
        FilesUploaded: 0
        FilesDownloaded: 3
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 6770
        KnownFileSize: 177084970810
        LastBackupDate: 10/27/2018 12:12:19 AM (1540591939)
        BackupListCount: 6
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.3.12 (2.0.3.12_canary_2018-10-23)
        Messages: [
            2018-10-28 12:48:43 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-10-28 12:52:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-10-28 12:53:31 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6,61 KB),
            2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
            2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
        ]
        Warnings: []
        Errors: []
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-....dlist.zip.aes
        Value: [],
        Key: duplicati-....dindex.zip.aes
        Value: [],
        Key: duplicati-.....dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.3.12 (2.0.3.12_canary_2018-10-23)
    EndTime: 10/28/2018 12:58:32 PM (1540727912)
    BeginTime: 10/28/2018 12:57:44 PM (1540727864)
    Duration: 00:00:47.8916150
    Messages: [
        2018-10-28 12:48:43 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-10-28 12:52:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-10-28 12:53:31 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6,61 KB),
        2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
        2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
    ]
    Warnings: []
    Errors: []
ParsedResult: Success
Version: 2.0.3.12 (2.0.3.12_canary_2018-10-23)
EndTime: 10/28/2018 12:58:32 PM (1540727912)
BeginTime: 10/28/2018 12:48:43 PM (1540727323)
Duration: 00:09:48.9079800
Messages: [
    2018-10-28 12:48:43 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-10-28 12:52:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-10-28 12:53:31 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6,61 KB),
    2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed,
    2018-10-28 12:56:45 +01 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00,
...
]
Warnings: []
Errors: []

Any help is appreciated!

Regards,
Kudo


#2

Hi,
You can try this option:
–accept-any-ssl-certificate=true

Good lucky


#3

if the suggestion from @luisBSBDATA (thanks for that!) doesn’t make email work, you might need to do more experiments, for example does “command line” mean a true shell or the web UI job Commandline option which would run as the same user as the scheduled job (might not be true for real command line)? You can also get the logging of email from the web UI job in several ways, for example MENU --> About --> Show log --> Live --> Profiling, or add the –log-file and –log-file-log-level=Profiling options. Here’s some output of my email sending:

2018-10-30 06:52:30 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:01:59.796
2018-10-30 06:52:34 -04 - [Profiling-Duplicati.Library.Modules.Builtin.SendMail-SendMailResult]: Whole SMTP communication: Connected to smtp://smtpauth.earthlink.net:587/?starttls=always
S: 220-elasmtp-mealy.atl.sa.earthlink.net ESMTP Exim 4 #1 Tue, 30 Oct 2018 06:52:33 -0400
<setup then email>
C: QUIT
S: 221 elasmtp-mealy.atl.sa.earthlink.net closing connection

2018-10-30 06:52:34 -04 - [Information-Duplicati.Library.Modules.Builtin.SendMail-SendMailComplete]: Email sent successfully using server: smtp://smtpauth.earthlink.net:587/?starttls=always
2018-10-30 06:52:34 -04 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation Backup has completed

If you see something then maybe it will give clues to what went wrong. If you see nothing, that’s a clue too. :grin:


Email sends sometimes
#4

Hi
Thanks for your replies. @ts678 The command line mentioned above is in the web UI, so it should speak for equal conditions for the scheduled job and the web UI command line job, right?

I have now changed the default settings from Verbose to Profiling for --console-log-level=Profiling and added the following:

--log-file=true
--log-file-log-level=Profiling

Still, I get no email report and does not see any indication of SendMail module execution in the profiling live log during scheduled backup execution.

@luisBSBDATA, I did also add --accept-any-ssl-certificate=true to the default settings. I had this but removed it yesterday for testing and it didn’t seem to have any effect so I left it off. Now I see after a couple of days that it has caused authentication issues during the following backup runs. Now, with the setting on, I receive the following explanation when testing SendMail in the web UI command line:

The option --accept-any-ssl-certificate is not supported because the module Configure http requests (http-options) is not currently loaded
...
Failed to send message: System.IO.IOException: The authentication or decryption has failed. --&gt; System.IO.IOException: The authentication or decryption has failed. --&gt; Mono.Security.Protocol.Tls.TlsException: Invalid certificate received from server. Error code: 0xffffffff800b010a =&gt; The authentication or decryption has failed.

In the manual it says that http requests (http-options) is loaded automatically. How can I check it for being loaded correctly?

Thanks


#5

It seems at first glance like it should be the same. Please confirm this attempt to capture what’s been done:

  • Double quotes were not in the original copied text (if they were, please describe how they got there).
  • “My static configuration” is from MENU --> Settings --> Default options box, after clicking “Edit as list”.
  • “My command line configuration” is from job’s Commandline Advanced options box with “Edit as text”.
  • Run “backup” command now button sends email.
  • Same job run on scheduler does not.send email.

If above is so, I agree it’s very strange. If you do “Run now” on the job menu, which email result do you get?

I see the manual link (and 2.0.3.3) explained that option poorly. The web UI in 2.0.3.12 explains it’s usage as:

Logs information to the file specified
Default value: “”

and Duplicati.CommandLine.exe help log-file does even better:

–log-file (Path): Log internal information to a file
Logs information to the file specified

Sorry about that. You might now have a file called “true” somewhere. Did live log show the lines that say
“Running Backup took”, then “The operation Backup has completed”, and somehow omit the SendMail?
Maybe when you get the --log-file straightened out, comparisons between ways of running will be easier.


#6

@ts678 Today I’ve got Error: TrustFailure (The authentication or decryption has failed. and probably solved it by upgrading the Qmono package from v4.xxxx to v5.14.0.177 on the NAS due to inspiration from this thread Problem with OneDrive on Synology NAS. I am not sure the ca-certificates.crt is up to date yet and I need to dig more into it to find out. I still receive the The option --accept-any-ssl-certificate is not supported because the module Configure http requests (http-options) is not currently loaded when executing the “send-mail” (but not “backup”) from UI command line AND I still receive email reports only here. Run now on the same job does not send any email report… I have attached the “true” log file for all three runs. Log files.zip (14.3 KB)
My UI command line settings for the job are:

--compression-module=zip
--compression-extension-file="/share/CACHEDEV1_DATA/.qpkg/Duplicati/Duplicati/default_compressed_extensions.txt"
--debug-retry-errors=true
--send-mail-any-operation=true
--send-mail-body="%RESULT%"
--send-mail-from="Duplicati Backup <...@gmail.com>"
--send-mail-level="all"
--send-mail-subject="%PARSEDRESULT% - %backup-name% - Duplicati %OPERATIONNAME% report"
--send-mail-to="... <...@gmail.com>"
--send-mail-url="smtp://smtp.gmail.com:587/?starttls=always"
--send-mail-username="...@gmail.com"
--send-mail-password="..."
--console-log-level=Profiling
--accept-any-ssl-certificate=true
--log-file=true
--log-file-log-level=Profiling
--backup-name=Testbackup
--dbpath=/share/CACHEDEV1_DATA/.qpkg/Duplicati/.config/Duplicati/70857267667277666972.sqlite
--encryption-module=aes
--dblock-size=50mb
--passphrase=...
--retention-policy=1W:1D,4W:1W,12M:1M
--disable-module=console-password-input

For now, I can tell:
@ts678 Double quotes were not in the original copied text (if they were, please describe how they got there).
I have done some trial and error on adding double quotes except until it caused errors. I experienced that some disappears when page is reloaded. I don’t suspect those to cause any troubles but I can be wrong.

@ts678

“My static configuration” is from MENU --> Settings --> Default options box, after clicking “Edit as list”
“My command line configuration” is from job’s Commandline Advanced options box with “Edit as text”.
Run “backup” command now button sends email.
Same job run on scheduler does not.send email.

And the answers are 4x yes!

Thanks


#7

Hi,

I detected that if your declare the setup of the email is on “static configuration”, send mail isn’t work.

You can try to declare your send mail setup on a advanced options on the step number 5 when your add or edit the backup job.


#8

@luisBSBDATA I have tried moving the general configuration to the job configuration (edit job -> step 5) without any differences, unfortunately.

Status is still:

  • Send-mail through UI command line: Delivers email report, but warns The option --accept-any-ssl-certificate is not supported because the module Configure http requests (http-options) is not currently loaded.
  • Backup through UI command line: Delivers email report with no warnings.
  • Ordinary “Backup now”: No execution of sendmail module, no warnings and no email report.

@ts678 and @JonMikelV

  • What is the difference between the three execution methods? Can it be debugged?
  • Do you think the problem is related to the Mono installation/configuration or Duplicati?

Thanks, everyone.


#9

I suspect the issue is related to a parameter parsing bug causing an error BEFORE the send mail step and when that error is handled, it (incorrectly) skips trying to send emails.

I’d suggest making a simple test job (with job level email settings) that just backs up one file to a local folder and see if that works.


#10

Hi,
Make sure if you have a Duplicati.Library.Modules.Builtin.dll file on the root installer folder.


#11

Hi,

Thank you for your efforts.

@JonMikelV I have tried making a local job with a single file, without encryption and only mail parameters in the job configuration. No difference, unfortunately!

@luisBSBDATA I have the Duplicati.Library.Modules.Builtin.dll file in place.

If this problem is isolated to me, I should be able to start from fresh. I havn’t checked if the QNAP uninstallation mechanism is cleaning entirely and will try to look into that. Anything I should be aware of?

I have had no success digging into the warning: The option --accept-any-ssl-certificate is not supported because the module Configure http requests (http-options) is not currently loaded.

Any suggestions left to try out? How about the --disable-module=""? Should I try testing by exclusion? Which modules are preferable?

Thanks.


#12

Well let’s try this - assuming the issue is related to your running environment (QNAP) perhaps somebody else who’s installed on QNAP (such as @jcastillo, @Fifi, @usefulvid, or maybe @Wim_Jansen) can let us know if email has (or has not) worked for them.


#13

No qnap here, sorry…


#14

Hi @Kudo ,

now exist a new version 2.0.3.13 of duplicati. Yo can try to install this new version.

You should verify to update your qnap firmware is to last version.


#15

For me, extraneous double-quotes as in --send-mail-level="all" result in no email sent, so please remove those if they’re still in use (possibly good advice for any value that you’re typing into the web UI).

You might have noticed that email is sent or not sent after the backup. This is because the backup result generates an unquoted word such as Unknown, Success, Warning, Error, Fatal which is matched against given --send-mail-level component(s). A special-case word is All, again unquoted, which is how send-mail supplies it, therefore it works. If yours is still quoted, it can not match, therefore no email will ever be sent.

What this doesn’t explain is how a job that fails to send mail at “Run now” does so clicking “Commandline”, however it’s conceivable that your quoting gets removed somehow. For me, I just get the same non-email.

The --accept-any-ssl-certificate option is listed on the dropdown only on “Configure http requests” so that possibly explains why it’s not accepted. Are you using a destination that uses http? Although mail sending frequently uses the same sort of SSL/TLS encryption that http uses, its code can be entirely independent.

Q: Why do I get The remote certificate is invalid according to the validation procedure when I try to Connect? from MailKit (which Duplicati uses) looks like a similar way to ignore errors, but Duplicati doesn’t support it. Things are probably OK in SSL/TLS. Updating Mono helps, plus you’re sometimes able to send the email. When you’re not able, it looks superficially like it’s not wanting to even try, thus I point at --send-mail-level.

In addition to quote removal and certificate-acceptance setting removal, you could see if you can get http notifications to work, e.g. to https://www.duplicati-monitoring.com/ and in addition to possibly adding clues, you’ll then have an alternative notification if somehow we can’t get direct email from Duplicati working well.


Send-mail and --accept-any-ssl-certificate doesn't work with 2.0.4.1_experimental
#16

Thanks! I am able to spend more time on it tomorrow and then return to you.


#17

Hi @luisBSBDATA, @ts678, @JonMikelV.

Finally, the mystery is solved. I needed to remove all double quotes in the text configuration and now I receive email reports from all my backup jobs! YES! Both if it is configured in the general configuration and in the job configuration.

--send-mail-any-operation=true
--send-mail-body=%RESULT%
--send-mail-from=Duplicati Backup <...@gmail.com>
--send-mail-level=All
--send-mail-subject=%PARSEDRESULT% - %backup-name% - Duplicati %OPERATIONNAME% report
--send-mail-to=Me <...@gmail.com>
--send-mail-url=smtp://smtp.gmail.com:587/?starttls=always
--send-mail-username=...@gmail.com
--send-mail-password=...

The reason for success without --accept-any-ssl-certificate=true may be my upgrade of qMono (and the ca-certificates.crt file) on the QNAP, I guess.

I have missed the reports since I upgraded from 2.0.2.8 to 2.0.3.3 and back without changing configuration parameters and I remember being inspired by the following forum post when I added qoutes everywhere as an attempt to solve the missing email reports.

Nevermind! It has been a pleasure to experience your persistent support. Thank you all. It worked!

/Kudo


#18

So I’m sensing an opportunity for improvement by somehow reporting an error with the bad email parameters… :slight_smile: