Crash trying to send email

Support
#1

I’m running Duplicati 2.0.5.1_beta_2020-01-18 on Ubuntu 20.04 on a tinkerboard. It has been working for for quite some time. However recently I’ve been getting crash messages in my system log. It appears to be crashing while constructing email messages. I’m running a local Postfix mail server and that is working fine for other applications.

My options are

--send-mail-level=Warning,Error,Fatal
--send-mail-subject=tinker: Duplicati %OPERATIONNAME% report for %backup-name% - %RESULT%
--send-mail-to=user@somehost
--send-mail-url=smtp://localhost:25/?starttls=never

The system crash log is here

duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011Native Crash Reporting
duplicati-server[13455]: =================================================================
duplicati-server[13455]: Got a SIGSEGV while executing native code. This usually indicates
duplicati-server[13455]: a fatal error in the mono runtime or one of the native libraries
duplicati-server[13455]: used by your application.
duplicati-server[13455]: =================================================================
duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011Native stacktrace:
duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011 (No frames)
duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011Telemetry Dumper:
duplicati-server[13455]: =================================================================
duplicati-server[13455]: Pkilling 0x2928669744x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2982147120x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2922378288x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x3059659824x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2969560112x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2918691888x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2917135408x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2973758512x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x3069241792x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x3002659888x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2931094576x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2926294064x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2914690096x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2984858672x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2932147248x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2915742768x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2903503920x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2901914672x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2976883760x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2977936432x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2978989104x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2999972912x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2996827184x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2920461360x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2980041776x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2927617072x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2990535728x from 0x2993681456x
duplicati-server[13455]: Pkilling 0x2981094448x from 0x2993681456x
duplicati-server[13752]: Could not exec mono-hang-watchdog, expected on path '/etc/../bin/mono-hang-watchdog' (errno 2)
duplicati-server[13455]: Entering thread summarizer pause from 0x2993681456x
duplicati-server[13455]: Finished thread summarizer pause from 0x2993681456x.
duplicati-server[13455]: Failed to create breadcrumb file (null)/crash_hash_0x7f7637a7c
duplicati-server[13455]: Waiting for dumping threads to resume
duplicati-server[13759]: =================================================================
duplicati-server[13759]: #011External Debugger Dump:
duplicati-server[13759]: =================================================================
duplicati-server[13759]: mono_gdb_render_native_backtraces not supported on this platform, unable to find gdb or lldb
duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011Basic Fault Address Reporting
duplicati-server[13455]: =================================================================
duplicati-server[13455]: Memory around native instruction pointer (0xb6e8cd64):0xb6e8cd54  00 01 30 bc 70 47 00 bf 2d e9 f0 4f 87 b0 00 bf  ..0.pG..-..O....
duplicati-server[13455]: 0xb6e8cd64  45 6a eb 08 00 f0 9a 81 15 f0 01 05 06 46 56 f8  Ej...........FV.
duplicati-server[13455]: 0xb6e8cd74  20 3f 04 46 18 bf 80 25 0e e0 43 f0 01 01 56 e8   ?.F...%..C...V.
duplicati-server[13455]: 0xb6e8cd84  00 2f 9a 42 05 d1 46 e8 00 10 00 28 f7 d1 bf f3  ./.B..F....(....
duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011Managed Stacktrace:
duplicati-server[13455]: =================================================================
duplicati-server[13455]: #011  at <unknown> <0xffffffff>
duplicati-server[13455]: #011  at System.Object:__icall_wrapper_mono_generic_class_init <0x00037>
duplicati-server[13455]: #011  at MimeKit.ParserOptions:.ctor <0x000a3>
duplicati-server[13455]: #011  at MimeKit.ParserOptions:.cctor <0x00077>
duplicati-server[13455]: #011  at System.Object:runtime_invoke_void <0x0007b>
duplicati-server[13455]: #011  at <unknown> <0xffffffff>
duplicati-server[13455]: #011  at Duplicati.Library.Modules.Builtin.SendMail:SendMessage <0x00117>
duplicati-server[13455]: #011  at Duplicati.Library.Modules.Builtin.ReportHelper:OnFinish <0x00657>
duplicati-server[13455]: #011  at Duplicati.Library.Main.Controller:OnOperationComplete <0x0023f>
duplicati-server[13455]: #011  at Duplicati.Library.Main.Controller:RunAction <0x006d3>
duplicati-server[13455]: #011  at Duplicati.Library.Main.Controller:Backup <0x002bf>
duplicati-server[13455]: #011  at Duplicati.Server.Runner:Run <0x01133>
duplicati-server[13455]: #011  at <>c:<SetWorkerThread>b__45_0 <0x0001b>
duplicati-server[13455]: #011  at Duplicati.Library.Utility.WorkerThread`1:Runner <0x00623>
duplicati-server[13455]: #011  at System.Threading.ThreadHelper:ThreadStart_Context <0x000df>
duplicati-server[13455]: #011  at System.Threading.ExecutionContext:RunInternal <0x0021b>
duplicati-server[13455]: #011  at System.Threading.ExecutionContext:Run <0x0002b>
duplicati-server[13455]: #011  at System.Threading.ExecutionContext:Run <0x0005f>
duplicati-server[13455]: #011  at System.Threading.ThreadHelper:ThreadStart <0x00047>
duplicati-server[13455]: #011  at System.Object:runtime_invoke_void__this__ <0x000eb>
duplicati-server[13455]: =================================================================
systemd[1]: duplicati.service: Main process exited, code=exited, status=134/n/a
systemd[1]: duplicati.service: Failed with result 'exit-code'.
systemd[1]: duplicati.service: Scheduled restart job, restart counter is at 1039.
systemd[1]: Stopped Duplicati web-server.
systemd[1]: Started Duplicati web-server.
#2

Are you set up to receive mono updates from mono-project.com, and did you update the system then?

Mono Releases today says “The latest stable release is 6.12.0 Stable (6.12.0.107).”

Native Crash Reporting #20834 from Feb 9 reports a crash a bit like yours. What is mono --version?

I’m not sure if package tools show install dates, but you could possibly ls -lc on a mono file to guess.

Beyond that I don’t have any ideas. The stack (which may or may not be reliable) looks like “safe” code

#3

Yes, I get updates from mono-project.com

>mono --version
Mono JIT compiler version 6.12.0.107 (tarball Thu Dec 10 05:42:38 UTC 2020)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
        TLS:           __thread
        SIGSEGV:       normal
        Notifications: epoll
        Architecture:  armel,vfp+hard
        Disabled:      none
        Misc:          softdebug 
        Interpreter:   yes
        LLVM:          yes(610)
        Suspend:       preemptive
        GC:            sgen (concurrent by default)
#4

Did that go in when the problem began? That would be very solid evidence of a link. Check file times.
Possibly ls -lcrt /usr/lib/libmono* will give you a date. I’m far from a mono internals expert…

If mono had a regression, you can watch their issue for a response, and also try downgrading mono.
Duplicati 2.0.5.1 Beta needs at least mono version 5, and the next Beta will need at least mono 5.10.

Download at bottom has official advice on old mono versions. I’d note they also have newer previews.
There is unofficial advice elsewhere on the Internet about old mono versions. Maybe some will fit you.

#5

The mono files were written December 19th, 2020. I don’t believe I had problems for that long. Although it appears that duplicati only crashes when trying to send an email.

Looking at logs over the past week my recent backups have been working, but I do have a warning that I haven’t seen before.

[Warning-Duplicati.Library.DynamicLoader.DynamicLoader`1-SoftError]: Failed to load process type System.Reactive.Concurrency.DispatcherScheduler assembly /usr/lib/duplicati/System.Reactive.dll, error message: Could not load type of field 'System.Reactive.Concurrency.DispatcherScheduler:<Dispatcher>k__BackingField' (0) due to: Could not load file or assembly 'WindowsBase, Version=4.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35' or one of its dependencies.

This backup would have tried to generate an email due to the warnings and duplicati crashed again trying to send an email.

#6

The SEND-MAIL command can test that by itself, and you can probably watch About → Show log → Live → Profiling to see a backup-free log of interactions with the mail server, but I’m not certain it ran that long.

Sometimes true CLI puts out additional messages, so you could Export As Command-line and either just run regular backup (or backup enhanced with –send-mail-level=all) or convert the command to send-mail.

#7

Using the send mail test command by itself doesn’t cause the crash.

#8

was seen in Warning: Could not load file or assembly WindowsBase, Version=4.0.0.0 and confirmed fixed by installing mono-complete rather than a smaller package like mono-devel,. That might at least avoid that warning, and I have no idea whether it would help whatever’s wrong with email.

You could test a profiling log with a small backup, because a big backup will produce an enormous log file. As mentioned before, doing the small backup on true CLI might also reveal more, but no promises on that.

#9

I installed mono-complete and restarted duplicati.

I then did a small backup and told it to always send email and added a profiling log.
This is the end of the log

2021-02-19 20:18:00 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2021-02-19 20:18:00 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b2063ce4f26ec48c790656c8cbbdb11e2.dblock.zip.aes (33.38 MB)
2021-02-19 20:18:04 -06 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded 33.38 MB in 00:00:04.4141050, 7.56 MB/s
2021-02-19 20:18:04 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b2063ce4f26ec48c790656c8cbbdb11e2.dblock.zip.aes (33.38 MB)
2021-02-19 20:18:04 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:04.427
2021-02-19 20:18:04 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b2063ce4f26ec48c790656c8cbbdb11e2.dblock.zip.aes"
2021-02-19 20:18:04 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b2063ce4f26ec48c790656c8cbbdb11e2.dblock.zip.aes" took 0:00:00:00.008
2021-02-19 20:18:05 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "LogData" WHERE "Timestamp" < 1611195485
2021-02-19 20:18:05 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "LogData" WHERE "Timestamp" < 1611195485 took 0:00:00:00.001
2021-02-19 20:18:05 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "RemoteOperation" WHERE "Timestamp" < 1611195485
2021-02-19 20:18:05 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "RemoteOperation" WHERE "Timestamp" < 1611195485 took 0:00:00:00.001
2021-02-19 20:18:05 -06 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2021-02-19 20:18:05 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000
2021-02-19 20:18:05 -06 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:02:08.215

This is my system log for that time period:

Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: #011Native Crash Reporting
Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: Got a SIGSEGV while executing native code. This usually indicates
Feb 19 20:18:05 tinker duplicati-server[2694]: a fatal error in the mono runtime or one of the native libraries
Feb 19 20:18:05 tinker duplicati-server[2694]: used by your application.
Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: #011Native stacktrace:
Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: #011 (No frames)
Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: #011Telemetry Dumper:
Feb 19 20:18:05 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2973754416x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2966410288x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2982143024x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2962220080x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2997875760x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2968515632x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x3060397104x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2903499824x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2978985008x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x3003409456x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2974807088x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2981090352x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2967462960x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2983195696x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2977932336x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x3069987264x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2963272752x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2904552496x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2991584304x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x3001021488x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2985907248x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2980037680x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Pkilling 0x2960114736x from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[3247]: Could not exec mono-hang-watchdog, expected on path '/etc/../bin/mono-hang-watchdog' (errno 2)
Feb 19 20:18:05 tinker duplicati-server[2694]: Entering thread summarizer pause from 0x2994730032x
Feb 19 20:18:05 tinker duplicati-server[2694]: Finished thread summarizer pause from 0x2994730032x.
Feb 19 20:18:05 tinker duplicati-server[2694]: Failed to create breadcrumb file (null)/crash_hash_0x7f75a5a7c
Feb 19 20:18:05 tinker duplicati-server[2694]: Waiting for dumping threads to resume
Feb 19 20:18:06 tinker duplicati-server[3249]: =================================================================
Feb 19 20:18:06 tinker duplicati-server[3249]: #011External Debugger Dump:
Feb 19 20:18:06 tinker duplicati-server[3249]: =================================================================
Feb 19 20:18:06 tinker duplicati-server[3249]: mono_gdb_render_native_backtraces not supported on this platform, unable to find gdb or lldb
Feb 19 20:18:06 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:06 tinker duplicati-server[2694]: #011Basic Fault Address Reporting
Feb 19 20:18:06 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:06 tinker duplicati-server[2694]: Memory around native instruction pointer (0xb6f42d64):0xb6f42d54  00 01 30 bc 70 47 00 bf 2d e9 f0 4f 87 b0 00 bf  ..0.pG..-..O....
Feb 19 20:18:06 tinker duplicati-server[2694]: 0xb6f42d64  45 6a eb 08 00 f0 9a 81 15 f0 01 05 06 46 56 f8  Ej...........FV.
Feb 19 20:18:06 tinker duplicati-server[2694]: 0xb6f42d74  20 3f 04 46 18 bf 80 25 0e e0 43 f0 01 01 56 e8   ?.F...%..C...V.
Feb 19 20:18:06 tinker duplicati-server[2694]: 0xb6f42d84  00 2f 9a 42 05 d1 46 e8 00 10 00 28 f7 d1 bf f3  ./.B..F....(....
Feb 19 20:18:06 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:06 tinker duplicati-server[2694]: #011Managed Stacktrace:
Feb 19 20:18:06 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at <unknown> <0xffffffff>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Object:__icall_wrapper_mono_generic_class_init <0x00037>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at MimeKit.ParserOptions:.ctor <0x000a3>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at MimeKit.ParserOptions:.cctor <0x00077>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Object:runtime_invoke_void <0x0007b>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at <unknown> <0xffffffff>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Library.Modules.Builtin.SendMail:SendMessage <0x00117>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Library.Modules.Builtin.ReportHelper:OnFinish <0x00657>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Library.Main.Controller:OnOperationComplete <0x0023f>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Library.Main.Controller:RunAction <0x006d3>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Library.Main.Controller:Backup <0x002bf>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Server.Runner:Run <0x01133>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at <>c:<SetWorkerThread>b__45_0 <0x0001b>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at Duplicati.Library.Utility.WorkerThread`1:Runner <0x00623>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Threading.ThreadHelper:ThreadStart_Context <0x000df>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Threading.ExecutionContext:RunInternal <0x0021b>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Threading.ExecutionContext:Run <0x0002b>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Threading.ExecutionContext:Run <0x0005f>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Threading.ThreadHelper:ThreadStart <0x00047>
Feb 19 20:18:06 tinker duplicati-server[2694]: #011  at System.Object:runtime_invoke_void__this__ <0x000eb>
Feb 19 20:18:06 tinker duplicati-server[2694]: =================================================================
Feb 19 20:18:06 tinker systemd[1]: duplicati.service: Main process exited, code=exited, status=134/n/a
Feb 19 20:18:06 tinker systemd[1]: duplicati.service: Failed with result 'exit-code'.
Feb 19 20:18:06 tinker systemd[1]: duplicati.service: Scheduled restart job, restart counter is at 1.
Feb 19 20:18:06 tinker systemd[1]: Stopped Duplicati web-server.
#10

Opened issue for the crash with mono at Crash executing native code to send email · Issue #20859 · mono/mono · GitHub