Check stopped half way. Why?

Support
#1

I’ve created an unscheduled schedule to run a massive check ‘-a -files’ once on a local database. After few days of running it simply stopped, seemingly cleanly, halfway:

image
image2502×522 38.9 KB

Full log here

Running check command from /var/services/homes/duplicacy-web/.duplicacy-web/repositories/localhost/all
Options: [-log check -storage tuchka -a -files -a -tabular]
2020-05-12 18:56:59.958 INFO STORAGE_SET Storage set to /volume1/Backups/duplicacy
2020-05-12 18:57:00.020 INFO SNAPSHOT_CHECK Listing all chunks
2020-05-12 18:57:30.480 INFO SNAPSHOT_CHECK 5 snapshots and 283 revisions
2020-05-12 18:57:30.492 INFO SNAPSHOT_CHECK Total chunk size is 1425G in 302414 chunks
2020-05-12 22:03:48.242 INFO SNAPSHOT_VERIFY All files in snapshot users-imac at revision 86 have been successfully verified
2020-05-13 00:59:06.755 INFO SNAPSHOT_VERIFY All files in snapshot users-imac at revision 126 have been successfully verified
2020-05-13 03:28:45.316 INFO SNAPSHOT_VERIFY All files in snapshot users-imac at revision 135 have been successfully verified
2020-05-13 06:18:24.769 INFO SNAPSHOT_VERIFY All files in snapshot users-imac at revision 150 have been successfully verified
2020-05-13 09:18:54.001 INFO SNAPSHOT_VERIFY All files in snapshot users-imac at revision 172 have been successfully verified
2020-05-13 11:50:41.796 INFO SNAPSHOT_VERIFY All files in snapshot alex-iMacPro at revision 1 have been successfully verified
2020-05-13 14:10:00.223 INFO SNAPSHOT_VERIFY All files in snapshot alex-iMacPro at revision 6 have been successfully verified
2020-05-13 17:22:34.653 INFO SNAPSHOT_VERIFY All files in snapshot alex-iMacPro at revision 13 have been successfully verified
2020-05-13 20:44:23.588 INFO SNAPSHOT_VERIFY All files in snapshot alex-iMacPro at revision 14 have been successfully verified
2020-05-13 22:07:25.730 INFO SNAPSHOT_VERIFY All files in snapshot alex-imac at revision 146 have been successfully verified
2020-05-14 00:35:32.020 INFO SNAPSHOT_VERIFY All files in snapshot alex-imac at revision 860 have been successfully verified
2020-05-14 01:49:28.674 INFO SNAPSHOT_VERIFY All files in snapshot alex-imac at revision 1257 have been successfully verified
2020-05-14 03:13:38.341 INFO SNAPSHOT_VERIFY All files in snapshot alex-imac at revision 1803 have been successfully verified
2020-05-14 04:41:10.916 INFO SNAPSHOT_VERIFY All files in snapshot alex-imac at revision 2094 have been successfully verified
2020-05-14 05:40:15.196 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 1 have been successfully verified
2020-05-14 06:33:59.579 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 133 have been successfully verified
2020-05-14 07:16:45.795 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 361 have been successfully verified
2020-05-14 07:49:09.360 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 588 have been successfully verified
2020-05-14 08:28:13.395 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 629 have been successfully verified
2020-05-14 08:58:33.920 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 635 have been successfully verified
2020-05-14 09:08:16.269 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 643 have been successfully verified
2020-05-14 09:22:51.984 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 644 have been successfully verified
2020-05-14 09:44:00.820 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 647 have been successfully verified
2020-05-14 09:59:06.391 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 650 have been successfully verified
2020-05-14 10:15:53.959 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 651 have been successfully verified
2020-05-14 10:28:25.346 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 652 have been successfully verified
2020-05-14 10:43:41.907 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 654 have been successfully verified
2020-05-14 13:48:48.741 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 657 have been successfully verified
2020-05-14 16:54:26.656 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 661 have been successfully verified
2020-05-14 20:04:01.389 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 666 have been successfully verified
2020-05-15 00:12:36.282 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 671 have been successfully verified
2020-05-15 04:36:33.522 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 674 have been successfully verified
2020-05-15 08:18:54.915 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 675 have been successfully verified
2020-05-15 12:04:22.253 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 676 have been successfully verified
2020-05-15 15:42:58.416 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 677 have been successfully verified
2020-05-15 19:12:00.253 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 678 have been successfully verified
2020-05-15 22:52:37.198 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 680 have been successfully verified
2020-05-16 02:36:28.690 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 681 have been successfully verified
2020-05-16 06:17:57.867 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 683 have been successfully verified
2020-05-16 09:49:55.438 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 684 have been successfully verified
2020-05-16 13:24:17.587 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 685 have been successfully verified
2020-05-16 16:56:36.396 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 688 have been successfully verified
2020-05-16 20:21:25.181 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 689 have been successfully verified
2020-05-17 00:05:52.365 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 690 have been successfully verified

[snip]

2020-05-20 22:31:17.817 WARN DOWNLOAD_RESURRECT Fossil 0da2a486e748da7c5c365cc4d9adecc713ab9c120a3e2a4d8d25624ad8f65e3d has been resurrected
2020-05-20 22:31:21.331 WARN DOWNLOAD_RESURRECT Fossil 2a6cd986c323b4f83432acce29ecf4acb5f35b0b5ff4c936b04f7fc5947c7adb has been resurrected
2020-05-20 22:31:21.562 WARN DOWNLOAD_RESURRECT Fossil 9da13387900f19dcd2ebe79b81e53ea710fe3f3e53d0542d92d406b8ccd7c5ae has been resurrected
2020-05-20 22:31:23.571 WARN DOWNLOAD_RESURRECT Fossil 35f1a6f3f2d8ff6f9c9c795fdbf2e700192544aa486fa2060f4f71dab78bdaa1 has been resurrected
2020-05-20 22:31:28.743 WARN DOWNLOAD_RESURRECT Fossil f628676979f9eb62f24f75479e4e241ba7a88e637effb4b5c37c722847384f81 has been resurrected
2020-05-20 22:31:28.965 WARN DOWNLOAD_RESURRECT Fossil 15f7b824e5ad7a484e269998763b5b7b615c07667d812048c0000a4fce27139a has been resurrected
2020-05-20 22:31:29.765 WARN DOWNLOAD_RESURRECT Fossil 64725de546f7bd816f70682880ff892a05069ec89961a07996b25d25517a1981 has been resurrected
2020-05-20 22:31:30.592 WARN DOWNLOAD_RESURRECT Fossil 13d912ea83b45b0953a909f92faac4fd691fca98cfc420735cb1412a789c171c has been resurrected
2020-05-20 22:31:32.129 WARN DOWNLOAD_RESURRECT Fossil 430dc385fc82143e337eb2dc34a607eea44d7934cb8b0901aeded9610220a513 has been resurrected
2020-05-20 22:31:43.300 WARN DOWNLOAD_RESURRECT Fossil 64e6642fead04a2798bec6316aab68d1bd64b85a4937507f4f4e564e099bd7b3 has been resurrected
2020-05-20 22:31:43.736 WARN DOWNLOAD_RESURRECT Fossil fb5c6d3370d5dd3d78b49cdfb26c64a2b88f7c6f88109a0f8fe2c7e8677c34ce has been resurrected
2020-05-21 02:41:45.639 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 716 have been successfully verified
2020-05-21 02:41:45.653 WARN DOWNLOAD_RESURRECT Fossil 59d2d7ba17552af9c2b25cf7a9de9f18e8a94edb319de23a3d495a8d56e6190f has been resurrected
2020-05-21 02:41:45.939 WARN DOWNLOAD_RESURRECT Fossil b96d2716afad7ed0455489ef994a16508e39ea4b133bb7ca31d23805b5bebf2e has been resurrected
2020-05-21 02:41:49.413 WARN DOWNLOAD_RESURRECT Fossil 1220539548406509b5ca3b71fae8b4f58e243251a4a87029ce98822cbb1bf8ed has been resurrected
2020-05-21 02:41:49.709 WARN DOWNLOAD_RESURRECT Fossil 5a2cb7b564d9c7f4120064d85ccf8db31568933fb8126f9ff4f364cc9649fd8a has been resurrected
2020-05-21 02:41:51.651 WARN DOWNLOAD_RESURRECT Fossil 34e5a8961bb293dafd1170f85e04fddadf4ae3eb7ddd3d5ed7e46dcdf95847a5 has been resurrected
2020-05-21 02:41:56.779 WARN DOWNLOAD_RESURRECT Fossil 7a932a86ba380fc1da063315369aa15448a1825a625aa4a475c75362a88b0be2 has been resurrected
2020-05-21 02:41:58.785 WARN DOWNLOAD_RESURRECT Fossil c9772d767cb5e53dab212220cda1d7f97943a0128f2585749b8610ea0b8d60d7 has been resurrected
2020-05-21 02:42:09.359 WARN DOWNLOAD_RESURRECT Fossil 88c0ee5e2ba7eee8b29e61f957c62cc78adf53cc06277af0444c47e4191ae91c has been resurrected
2020-05-21 02:42:09.732 WARN DOWNLOAD_RESURRECT Fossil 8e90385d307cdfdfa73e5cc66d45cc29679a9a70f731f3fb16d2e1d92e8d5679 has been resurrected
2020-05-21 06:30:56.797 WARN DOWNLOAD_RESURRECT Fossil 3835f43388f2a915407996992eed4965a92fa91b2308d37337830285eabdc183 has been resurrected
2020-05-21 06:30:56.902 INFO SNAPSHOT_VERIFY All files in snapshot alexmbp at revision 717 have been successfully verified

alexmbp snapshot has 1128 revisions btw.

No duplicacy processes other than UI

alex@Tuchka:~$ sudo ps -ax |grep duplicacy | grep -v grep
18377 ?        Ssl    0:07 /var/services/homes/duplicacy-web/duplicacy_web_linux_x64_1.3.0
alex@Tuchka:~$

The datastore is 1.5TB with about 300k chunks. alexmbp has about 200k files. Device (synology) duplicacy runs on has 32GB of RAM with 29GB available.

I have removed the DUPLICACY_ATTRIBUTE_THRESHOLD flag that I had set before. Last time I looked at it it had consumed about 12GB. Could it just have exceeded some threshold and die?

Looking at memory utilization history it never even approached the limit:

image
image1844×1114 163 KB

#2

Did you check the main log ~/.duplicacy-web/logs/duplicacy_web.log?

I still think it was killed due to using too much memory. What does ulimit -a say?

#3 
$ ulimit -a
core file size          (blocks, -c) unlimited
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 127833
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 127833
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

Doesn’t seem to be limited in any way. and duplicacy_web.log does not have anything around that timestamp:

...
2020/05/21 06:00:01 Running /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.2 [-log backup -storage backblaze -stats]
2020/05/21 06:00:01 Set current working directory to /var/services/homes/duplicacy-web/.duplicacy-web/repositories/localhost/0
2020/05/21 06:01:19 Created log file /var/services/homes/duplicacy-web/.duplicacy-web/logs/backup-20200521-060119.log
2020/05/21 06:01:19 Running /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.2 [-log backup -storage cumulonimbus -stats]
2020/05/21 06:01:19 Set current working directory to /var/services/homes/duplicacy-web/.duplicacy-web/repositories/localhost/1
2020/05/21 06:03:31 Schedule Daily next run time: 2020-0521 07:00
2020/05/21 07:00:01 Starting schedule Daily at scheduled time 2020-0521 07:00
2020/05/21 07:00:01 Created log file /var/services/homes/duplicacy-web/.duplicacy-web/logs/backup-20200521-070001.log
2020/05/21 07:00:01 Running /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.2 [-log backup -storage backblaze -stats]
2020/05/21 07:00:01 Set current working directory to /var/services/homes/duplicacy-web/.duplicacy-web/repositories/localhost/0
2020/05/21 07:01:18 Created log file /var/services/homes/duplicacy-web/.duplicacy-web/logs/backup-20200521-070118.log
2020/05/21 07:01:18 Running /var/services/homes/duplicacy-web/.duplicacy-web/bin/duplicacy_linux_x64_2.5.2 [-log backup -storage cumulonimbus -stats]
2020/05/21 07:01:18 Set current working directory to /var/services/homes/duplicacy-web/.duplicacy-web/repositories/localhost/1
2020/05/21 07:03:37 Schedule Daily next run time: 2020-0521 08:00
2020/05/21 08:18:47 Failed to retrieve the machine id: machineid: open /etc/machine-id: no such file or directory
...

On a separate note, there are some weird log messages like these:

2020/05/18 14:03:47 The log file backup-20200417-100001.log has been deleted
2020/05/18 14:03:47 The log file backup-20200417-100110.log has been deleted
2020/05/18 14:03:47 The log file backup-20200417-110001.log has been deleted
2020/05/18 14:03:47 The log file backup-20200417-110120.log has been deleted
2020/05/18 14:03:47 The log file backup-20200417-120001.log has been deleted
2020/05/18 14:03:47 Failed to delete the log file : remove /var/services/homes/duplicacy-web/.duplicacy-web/logs: directory not empty
2020/05/18 14:03:47 The log file backup-20200417-130001.log has been deleted
2020/05/18 14:03:47 Failed to delete the log file : remove /var/services/homes/duplicacy-web/.duplicacy-web/logs: directory not empty
2020/05/18 14:03:47 The log file backup-20200417-140001.log has been deleted
2020/05/18 14:03:47 Failed to delete the log file : remove /var/services/homes/duplicacy-web/.duplicacy-web/logs: directory not empty
2020/05/18 14:03:47 The log file backup-20200417-144016.log has been deleted
2020/05/18 14:03:47 Failed to delete the log file : remove /var/services/homes/duplicacy-web/.duplicacy-web/logs: directory not empty
2020/05/18 14:03:47 The log file backup-20200417-150001.log has been deleted
2020/05/18 14:03:47 Failed to delete the log file : remove /var/services/homes/duplicacy-web/.duplicacy-web/logs: directory not empty

The “directory not empty thing” – what is it trying to delete? Like wrong error message.

#4

If you open http://ip:port/print_stack_trace in the browser, the stack trace will be dumped to duplicacy_web.log. It will tell if the schedule is still running.

#5

Wow how cool is that!

2020/05/21 20:21:09 goroutine profile: total 8
1 @ 0x42f0bf 0x405dfa 0x405dd0 0x405afb 0x796088 0x4597f1
#   0x796087    gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun+0x57   /Users/chgang/zincbox/go/src/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:379

1 @ 0x42f0bf 0x42a7ca 0x429db6 0x485c4b 0x48825a 0x48823b 0x5048d2 0x521a12 0x520528 0x7007dd 0xcdd4da 0xcdd463 0xd31f01 0xcdaba1 0x42eccc 0x4597f1
#   0x429db5    internal/poll.runtime_pollWait+0x55     /usr/local/go/src/runtime/netpoll.go:182
#   0x485c4a    internal/poll.(*pollDesc).wait+0x9a     /usr/local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x488259    internal/poll.(*pollDesc).waitRead+0x1b9    /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x48823a    internal/poll.(*FD).Accept+0x19a        /usr/local/go/src/internal/poll/fd_unix.go:384
#   0x5048d1    net.(*netFD).accept+0x41            /usr/local/go/src/net/fd_unix.go:238
#   0x521a11    net.(*TCPListener).accept+0x31          /usr/local/go/src/net/tcpsock_posix.go:139
#   0x520527    net.(*TCPListener).Accept+0x47          /usr/local/go/src/net/tcpsock.go:260
#   0x7007dc    net/http.(*Server).Serve+0x22c          /usr/local/go/src/net/http/server.go:2859
#   0xcdd4d9    net/http.Serve+0x2819               /usr/local/go/src/net/http/server.go:2456
#   0xcdd462    main.onReady+0x27a2             /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_main.go:626
#   0xd31f00    main.runSystray+0x40                /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_systray_linux.go:12
#   0xcdaba0    main.main+0x530                 /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_main.go:286
#   0x42eccb    runtime.main+0x20b              /usr/local/go/src/runtime/proc.go:200

1 @ 0x42f0bf 0x43e118 0xb91850 0x4597f1
#   0xb9184f    go.opencensus.io/stats/view.(*worker).start+0xff    /Users/chgang/zincbox/go/src/go.opencensus.io/stats/view/worker.go:154

1 @ 0x42f0bf 0x43e118 0xd33086 0x4597f1
#   0xd33085    main.onReady.func3+0xc5 /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_main.go:495

1 @ 0x42f0bf 0x44a189 0x44a15f 0xd14127 0x4597f1
#   0x44a15e    time.Sleep+0x12e    /usr/local/go/src/runtime/time.go:105
#   0xd14126    main.detectWakeup+0x36  /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_schedule.go:474

1 @ 0x42f0bf 0x44a189 0x44a15f 0xd15846 0xd32c3e 0x4597f1
#   0x44a15e    time.Sleep+0x12e        /usr/local/go/src/runtime/time.go:105
#   0xd15845    main.checkSchedules+0x16a5  /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_schedule.go:604
#   0xd32c3d    main.onReady.func1+0x3d     /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_main.go:367

1 @ 0x6f6100 0x4597f1
#   0x6f6100    net/http.(*connReader).backgroundRead+0x0   /usr/local/go/src/net/http/server.go:676

1 @ 0x78d220 0x78d040 0x789c10 0xd33787 0x6fd024 0x7003f8 0x6fbfe1 0x4597f1
#   0x78d21f    runtime/pprof.writeRuntimeProfile+0x8f  /usr/local/go/src/runtime/pprof/pprof.go:708
#   0x78d03f    runtime/pprof.writeGoroutine+0x9f   /usr/local/go/src/runtime/pprof/pprof.go:670
#   0x789c0f    runtime/pprof.(*Profile).WriteTo+0x38f  /usr/local/go/src/runtime/pprof/pprof.go:329
#   0xd33786    main.logHTTPRequest.func1+0x516     /Users/chgang/zincbox/go/src/github.com/gilbertchen/duplicacy-web/dwe/dwe_main.go:776
#   0x6fd023    net/http.HandlerFunc.ServeHTTP+0x43 /usr/local/go/src/net/http/server.go:1995
#   0x7003f7    net/http.serverHandler.ServeHTTP+0xa7   /usr/local/go/src/net/http/server.go:2774
#   0x6fbfe0    net/http.(*conn).serve+0x850        /usr/local/go/src/net/http/server.go:1878

it does not look like it’s running. And there is no CLI process running either – so it did end. The question is why…

#6

I can’t find an explanation. If the goroutine that spawned the CLI process returned with an error, there should be a log message in duplicacy_web.log. If it returned successfully then the status of the check job should be updated instead of staying at 71/283.

What is the values of job_code and job_note for that check job in duplicacy.json?

#7

Indeed strange.

        {
            "email_password": "",
            "name": "Check Tuchka",
            "start": "12:00am",
            "max": "00:00",
            "frequency": 3600,
            "days": "0000000",
            "jobs": [
                {
                    "type": "check",
                    "computer": "localhost",
                    "repository": 0,
                    "source": "",
                    "storage": "tuchka",
                    "options": "-a -files",
                    "parallel": false,
                    "global_options": "",
                    "status_code": "",
                    "status_note": "71/283",
                    "status_log": "check-20200512-185659.log",
                    "status_time": "0001-01-01T00:00:00Z"
                }
            ],
            "email_enabled": false,
            "email_summary": false,
            "email_server": "",
            "email_username": "",
            "email_from": "",
            "email_to": "",
            "email_subject": "",
            "email_max_lines": 0,
            "email_excluded_logs": ""
        }
#8

I’m going to start the whole process again and let’s see what happens in a week, if this is reproducible.