No output when backing up to Backblaze B2

Getting Help
1

I’ve been using restic to backup files to my Backblaze B2 bucket via an automated weekly cron job for about a couple of years now. Upon checking a short while ago though, it looks like no backups have been created since July 2019.

When I manually run “restic snapshots”, I get no textual output on the terminal, even after leaving it for a few days. I just tried to create a new B2 bucket and initialize a new restic repository in it, but I run into the same issue. Creating a local repository seems to work though. I tried changing my B2 master key and updating the B2_ACCOUNT_KEY environment variable, but still the same issue. I was using restic 0.8.0 on Linux Mint eariler, so I tried testing with restic 0.9.6 and still the same issue.

Any ideas what might be going wrong are much appreciated.

2

Please take a look directly at the original B2 bucket. Every restic repository has a snaphots directory which contains 1 file per snapshot in your repository. Anything in there?

3

The newest file in the snapshots directory of the original bucket was created in July 2019. The newly created bucket is empty despite trying to initialize a new repository in it.

4

If you run a backup manually, does the output contain any errors?

5

Again, the command hangs with no textual response. Screenshot attached.

Screenshot from 2020-02-05 10-14-26
Screenshot from 2020-02-05 10-14-26936×110 18.9 KB

6

Can you run with -vv?

7

It gets stuck at this point:

% ~/bin/restic backup --cleanup-cache --files-from=include_uc.txt --exclude-file=exclude_uc.tx -vv
open repository
8

Hmm. Is the process doing any network I/O when it gets stuck? Can you kill it with SIGABRT and paste the resulting stack dump?

9

Sorry, am not that experienced with this type of troubleshooting. Could you please advise how I might go about getting this information.

10

Assuming you have no other restic processes running, try pkill -6 restic. If that doesn’t work, use ps aux | grep restic to find the PID of the restic process, then run kill -6 THAT_PID. You can do this in a separate terminal than the one running restic.

11

Thanks a lot @rawtaz. Here’s the output after killing the process using pkill -6 restic:

 % ~/bin/restic backup --cleanup-cache --files-from=include_uc.txt --exclude-file=exclude_uc.tx -vv
open repository
SIGABRT: abort
PC=0x45d1f3 m=0 sigcode=0

goroutine 19 [syscall]:
runtime.notetsleepg(0x14bdbc0, 0xb9d18986, 0x0)
	/usr/local/go/src/runtime/lock_futex.go:227 +0x34 fp=0xc000053760 sp=0xc000053730 pc=0x40aba4
runtime.timerproc(0x14bdba0)
	/usr/local/go/src/runtime/time.go:311 +0x2f1 fp=0xc0000537d8 sp=0xc000053760 pc=0x44c0c1
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc0000537e0 sp=0xc0000537d8 pc=0x45b2c1
created by runtime.(*timersBucket).addtimerLocked
	/usr/local/go/src/runtime/time.go:169 +0x10e

goroutine 1 [select]:
net/http.(*Transport).getConn(0xc000388000, 0xc0003d60c0, 0x0, 0xc0004f4e80, 0x5, 0xc0004cc7c0, 0x18, 0x0, 0x0, 0x0, ...)
	/usr/local/go/src/net/http/transport.go:1234 +0x553
net/http.(*Transport).roundTrip(0xc000388000, 0xc000229800, 0xc0002f0110, 0xc0002f017b, 0x1)
	/usr/local/go/src/net/http/transport.go:522 +0x603
net/http.(*Transport).RoundTrip(0xc000388000, 0xc000229800, 0xc0005e1ec0, 0x4e7a54, 0xc0002f0110)
	/usr/local/go/src/net/http/roundtrip.go:17 +0x35
github.com/restic/restic/internal/limiter.staticLimiter.roundTripper(0x0, 0x0, 0xf0d520, 0xc000388000, 0xc000229800, 0x762a63afc288f, 0x1344dcc4, 0x1344dcc4005e1f70)
	/restic/internal/limiter/static_limiter.go:63 +0x67
github.com/restic/restic/internal/limiter.staticLimiter.Transport.func1(0xc000229800, 0x5e3de98e, 0x1344dcc4, 0x762a63afc288f)
	/restic/internal/limiter/static_limiter.go:78 +0x4f
github.com/restic/restic/internal/limiter.roundTripper.RoundTrip(0xc0002187e0, 0xc000229800, 0x14b9140, 0xdda5bd, 0x18)
	/restic/internal/limiter/static_limiter.go:52 +0x30
github.com/kurin/blazer/b2.(*clientTransport).RoundTrip(0xc0002200e0, 0xc000229800, 0xc532c0, 0x9, 0x9)
	/restic/vendor/github.com/kurin/blazer/b2/b2.go:159 +0xe5
github.com/kurin/blazer/base.makeNetRequest(0xf20fe0, 0xc00013d8c0, 0xc000229700, 0xf0c5a0, 0xc0002200e0, 0xc0005d4a50, 0x2, 0x0)
	/restic/vendor/github.com/kurin/blazer/base/base.go:292 +0xfc
github.com/kurin/blazer/base.(*Bucket).DownloadFileByName(0xc000137e00, 0xf20fe0, 0xc00013d8c0, 0xdca1b6, 0x6, 0x0, 0x1, 0x0, 0x0, 0x0)
	/restic/vendor/github.com/kurin/blazer/base/base.go:1120 +0x62e
github.com/kurin/blazer/b2.(*b2Bucket).downloadFileByName(0xc00021a1a8, 0xf20fe0, 0xc00013d8c0, 0xdca1b6, 0x6, 0x0, 0x1, 0xc0005e2620, 0x2, 0x2, ...)
	/restic/vendor/github.com/kurin/blazer/b2/baseline.go:371 +0x91
github.com/kurin/blazer/b2.(*beBucket).downloadFileByName.func1.1(0x1, 0x1)
	/restic/vendor/github.com/kurin/blazer/b2/backend.go:434 +0x7a
github.com/kurin/blazer/b2.withReauth(0xf20fe0, 0xc00013d8c0, 0xf2cb00, 0xc000380090, 0xc0005e2578, 0xc0000302a0, 0xc000000208)
	/restic/vendor/github.com/kurin/blazer/b2/backend.go:766 +0x2b
github.com/kurin/blazer/b2.(*beBucket).downloadFileByName.func1(0xc0005e2620, 0xc0005e2608)
	/restic/vendor/github.com/kurin/blazer/b2/backend.go:444 +0xcd
github.com/kurin/blazer/b2.withBackoff(0xf20fe0, 0xc00013d8c0, 0xf2cb00, 0xc000380090, 0xc0005e26c8, 0x0, 0x0)
	/restic/vendor/github.com/kurin/blazer/b2/backend.go:747 +0x4d
github.com/kurin/blazer/b2.(*beBucket).downloadFileByName(0xc0005d28e0, 0xf20fe0, 0xc00013d8c0, 0xdca1b6, 0x6, 0x0, 0x1, 0xc0005e27c0, 0x40e7fb, 0xc000380088, ...)
	/restic/vendor/github.com/kurin/blazer/b2/backend.go:446 +0xf8
github.com/kurin/blazer/b2.(*Bucket).getObject(0xc0004692f0, 0xf20fe0, 0xc00013d8c0, 0xdca1b6, 0x6, 0xc82500, 0xc000218750, 0xc0005e2800)
	/restic/vendor/github.com/kurin/blazer/b2/b2.go:616 +0x80
github.com/kurin/blazer/b2.(*Object).ensure(0xc0005e29a0, 0xf20fe0, 0xc00013d8c0, 0x20, 0x20)
	/restic/vendor/github.com/kurin/blazer/b2/b2.go:563 +0x72
github.com/kurin/blazer/b2.(*Object).Attrs(0xc0005e29a0, 0xf20fe0, 0xc00013d8c0, 0x0, 0x0, 0xdca1b6)
	/restic/vendor/github.com/kurin/blazer/b2/b2.go:443 +0x5d
github.com/restic/restic/internal/backend/b2.(*b2Backend).Stat(0xc00021c500, 0xf20fe0, 0xc00013d8c0, 0xdca1b6, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/restic/internal/backend/b2/b2.go:223 +0x179
main.open(0xc00003a102, 0x13, 0xc00003a102, 0x13, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/restic/cmd/restic/global.go:650 +0x533
main.OpenRepository(0xc00003a102, 0x13, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x2, ...)
	/restic/cmd/restic/global.go:358 +0x96
main.runBackup(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc000338ee0, ...)
	/restic/cmd/restic/cmd_backup.go:413 +0x2da
main.glob..func2(0x14ab4e0, 0xc00013dac0, 0x0, 0x4, 0x0, 0x0)
	/restic/cmd/restic/cmd_backup.go:63 +0x1bf
github.com/spf13/cobra.(*Command).execute(0x14ab4e0, 0xc00013da40, 0x4, 0x4, 0x14ab4e0, 0xc00013da40)
	/restic/vendor/github.com/spf13/cobra/command.go:762 +0x460
github.com/spf13/cobra.(*Command).ExecuteC(0x14adfa0, 0xc00031feb0, 0x42d511, 0xe0fd98)
	/restic/vendor/github.com/spf13/cobra/command.go:852 +0x2ea
github.com/spf13/cobra.(*Command).Execute(...)
	/restic/vendor/github.com/spf13/cobra/command.go:800
main.main()
	/restic/cmd/restic/main.go:86 +0x3f

goroutine 6 [syscall]:
os/signal.signal_recv(0x0)
	/usr/local/go/src/runtime/sigqueue.go:147 +0x9c
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
	/usr/local/go/src/os/signal/signal_unix.go:29 +0x41

goroutine 7 [chan receive]:
github.com/restic/restic/internal/restic.init.0.func1.1()
	/restic/internal/restic/lock.go:257 +0xb3
created by github.com/restic/restic/internal/restic.init.0.func1
	/restic/internal/restic/lock.go:254 +0x35

goroutine 17 [chan receive]:
github.com/restic/restic/internal/restic.init.2.func1(0xc000096120)
	/restic/internal/restic/progress_unix.go:17 +0x63
created by github.com/restic/restic/internal/restic.init.2
	/restic/internal/restic/progress_unix.go:16 +0xab

goroutine 20 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc000140eb0)
	/restic/vendor/go.opencensus.io/stats/view/worker.go:154 +0x100
created by go.opencensus.io/stats/view.init.0
	/restic/vendor/go.opencensus.io/stats/view/worker.go:32 +0x57

goroutine 21 [chan receive]:
main.CleanupHandler(0xc0001c8a20)
	/restic/cmd/restic/cleanup.go:62 +0x5d
created by main.init.0
	/restic/cmd/restic/cleanup.go:24 +0x67

goroutine 22 [select]:
github.com/restic/restic/internal/ui/termstatus.(*Terminal).run(0xc0001376e0, 0xf20fe0, 0xc000222140)
	/restic/internal/ui/termstatus/status.go:98 +0x16e
github.com/restic/restic/internal/ui/termstatus.(*Terminal).Run(0xc0001376e0, 0xf20fe0, 0xc000222140)
	/restic/internal/ui/termstatus/status.go:83 +0x7d
main.glob..func2.1(0x0, 0x0)
	/restic/cmd/restic/cmd_backup.go:61 +0x6d
gopkg.in/tomb%2ev2.(*Tomb).run(0xc000140f50, 0xc000358320)
	/restic/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
created by gopkg.in/tomb%2ev2.(*Tomb).Go
	/restic/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc7

goroutine 191 [IO wait]:
internal/poll.runtime_pollWait(0x7f92b6b5df88, 0x77, 0xc0000eb200)
	/usr/local/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc0003d2598, 0x77, 0xf21000, 0xc0003bb020, 0xc0003d2580)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitWrite(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).WaitWrite(...)
	/usr/local/go/src/internal/poll/fd_unix.go:498
net.(*netFD).connect(0xc0003d2580, 0xf21060, 0xc0003bb020, 0x0, 0x0, 0xf0d9a0, 0xc0004ccd00, 0x0, 0x0, 0x0, ...)
	/usr/local/go/src/net/fd_unix.go:152 +0x29d
net.(*netFD).dial(0xc0003d2580, 0xf21060, 0xc0003bb020, 0xf26d20, 0x0, 0xf26d20, 0xc0003d67e0, 0x0, 0x0, 0x40c638)
	/usr/local/go/src/net/sock_posix.go:149 +0xff
net.socket(0xf21060, 0xc0003bb020, 0xdc8154, 0x3, 0x2, 0x1, 0x0, 0x0, 0xf26d20, 0x0, ...)
	/usr/local/go/src/net/sock_posix.go:70 +0x1c0
net.internetSocket(0xf21060, 0xc0003bb020, 0xdc8154, 0x3, 0xf26d20, 0x0, 0xf26d20, 0xc0003d67e0, 0x1, 0x0, ...)
	/usr/local/go/src/net/ipsock_posix.go:141 +0x141
net.(*sysDialer).doDialTCP(0xc0003d2500, 0xf21060, 0xc0003bb020, 0x0, 0xc0003d67e0, 0xca3c80, 0x14d6498, 0x0)
	/usr/local/go/src/net/tcpsock_posix.go:65 +0xc2
net.(*sysDialer).dialTCP(0xc0003d2500, 0xf21060, 0xc0003bb020, 0x0, 0xc0003d67e0, 0xc0005c9460, 0x10, 0x10)
	/usr/local/go/src/net/tcpsock_posix.go:61 +0xd7
net.(*sysDialer).dialSingle(0xc0003d2500, 0xf21060, 0xc0003bb020, 0xf162a0, 0xc0003d67e0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/dial.go:578 +0x36e
net.(*sysDialer).dialSerial(0xc0003d2500, 0xf21060, 0xc0003bb020, 0xc0005c9460, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/dial.go:546 +0x221
net.(*Dialer).DialContext(0xc0000f6480, 0xf20fe0, 0xc00013d8c0, 0xdc8154, 0x3, 0xc0004cc7c0, 0x18, 0x0, 0x0, 0x0, ...)
	/usr/local/go/src/net/dial.go:424 +0x666
net/http.(*Transport).dial(0xc000388000, 0xf20fe0, 0xc00013d8c0, 0xdc8154, 0x3, 0xc0004cc7c0, 0x18, 0x0, 0x640d30, 0xc0002cf600, ...)
	/usr/local/go/src/net/http/transport.go:1040 +0x1f5
net/http.(*Transport).dialConn(0xc000388000, 0xf20fe0, 0xc00013d8c0, 0x0, 0xc0004f4e80, 0x5, 0xc0004cc7c0, 0x18, 0x0, 0xe0fd98, ...)
	/usr/local/go/src/net/http/transport.go:1478 +0x193e
net/http.(*Transport).dialConnFor(0xc000388000, 0xc0001e8f20)
	/usr/local/go/src/net/http/transport.go:1308 +0xdc
created by net/http.(*Transport).queueForDial
	/usr/local/go/src/net/http/transport.go:1277 +0x41d

goroutine 227 [select]:
net.(*netFD).connect.func2(0xf21060, 0xc0003bb020, 0xc0003d2580, 0xc00035cde0, 0xc00035cd80)
	/usr/local/go/src/net/fd_unix.go:129 +0xba
created by net.(*netFD).connect
	/usr/local/go/src/net/fd_unix.go:128 +0x275

rax    0xfffffffffffffffc
rbx    0x7012b86
rcx    0x45d1f3
rdx    0x0
rdi    0x14bdbc0
rsi    0x80
rbp    0xc0000536e8
rsp    0xc0000536a0
r8     0x0
r9     0x0
r10    0xc0000536d8
r11    0x202
r12    0x762a45f445083
r13    0x1
r14    0x762a45f445083
r15    0x0
rip    0x45d1f3
rflags 0x202
cs     0x33
fs     0x0
gs     0x0
12

Hi All

Just wanted to check in to see if you had any ideas on what may be going wrong based on the stack dump that I provided.

It’s been a while since my last backup and am beginning to get a bit nervous.

Thanks again for your help with this.

Warm Regards

13

@ragnarok The stacktrace looks like restic is stuck requesting the repository config from backblaze over and over again, but it fails each time. Can you try to manually download the config file of your repository?

The only reasonable way forward is to use a debug build of restic and check the log for what’s happening. That however requires you to build restic yourself. See https://github.com/restic/restic/blob/master/CONTRIBUTING.md#reporting-bugs for instructions on how to do that.

14

Gee! I’m really not quite sure what changed over the last few weeks, but I just retried running my backup script and it now miraculously works!!!

I guess I’ll post on this forum if the issue reoccurs down the line, but thank you so much for all your assistance trying to get to the bottom of this.

Warm Regards

1 Like
15

I just had a problem very similar to this one, and it turned out that my Pi-hole config was blocking DNS resolution of a backblazeb2.com server. Once I whitelisted that in Pi-hole, everything started working again.

1 Like
16

Hello,

I’ve recently run into the same issue with a script that hasn’t changed in a few years.

when I abort the task as per instructions above, I get the following:

SIGABRT: abort
PC=0x55d4711ed621 m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex(0x55d4727a9888, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7ffc22012da8, 0x55d471191f83, ...)
	runtime/sys_linux_amd64.s:567 +0x21
runtime.futexsleep(0x55d4727a9888, 0x0, 0xffffffffffffffff)
	runtime/os_linux.go:45 +0x46
runtime.notesleep(0x55d4727a9888)
	runtime/lock_futex.go:151 +0xa3
runtime.stopm()
	runtime/proc.go:1860 +0xc4
runtime.findrunnable(0xc00003a800, 0x0)
	runtime/proc.go:2407 +0xa13
runtime.schedule()
	runtime/proc.go:2567 +0x300
runtime.park_m(0xc0004b8d80)
	runtime/proc.go:2737 +0xa3
runtime.mcall(0x55d471aab720)
	runtime/asm_amd64.s:318 +0x53

goroutine 1 [select]:
net/http.(*Transport).getConn(0xc00041de00, 0xc000294000, 0x0, 0xc000090d90, 0x5, 0xc0000366c0, 0x21, 0x0, 0x0, 0x0, ...)
	net/http/transport.go:1350 +0x587
net/http.(*Transport).roundTrip(0xc00041de00, 0xc0004cf000, 0xc00067c060, 0xc00067c060, 0x55d471fc9c20)
	net/http/transport.go:569 +0x76d
net/http.(*Transport).RoundTrip(0xc00041de00, 0xc0004cf000, 0x55d4720be6e0, 0xc00067c060, 0xc000760010)
	net/http/roundtrip.go:17 +0x37
github.com/restic/restic/internal/limiter.staticLimiter.roundTripper(0x0, 0x0, 0x55d4720b28e0, 0xc00041de00, 0xc0004cf000, 0x2b2f819402bc1, 0xc031a1a7d8, 0x31a1a7d800725e78)
	github.com/restic/restic/internal/limiter/static_limiter.go:67 +0x69
github.com/restic/restic/internal/limiter.staticLimiter.Transport.func1(0xc0004cf000, 0x61040b1f, 0x31a1a7d8, 0x2b2f819402bc1)
	github.com/restic/restic/internal/limiter/static_limiter.go:82 +0x51
github.com/restic/restic/internal/limiter.roundTripper.RoundTrip(0xc0004b1ce0, 0xc0004cf000, 0x55d4727a8120, 0x55d471ab61b6, 0xe)
	github.com/restic/restic/internal/limiter/static_limiter.go:56 +0x32
github.com/kurin/blazer/b2.(*clientTransport).RoundTrip(0xc0004b72a0, 0xc0004cf000, 0xc000726020, 0x55d47164a71e, 0x55d471fe2c60)
	github.com/kurin/blazer@v0.5.3/b2/b2.go:159 +0xe7
github.com/kurin/blazer/base.makeNetRequest(0x55d4720c8c20, 0xc0034382c0, 0xc0004ce100, 0x55d4720b0ec0, 0xc0004b72a0, 0xc000678028, 0x4, 0xc000512fc0)
	github.com/kurin/blazer@v0.5.3/base/base.go:292 +0xfe
github.com/kurin/blazer/base.(*b2Options).makeRequest(0xc000500140, 0x55d4720c8c20, 0xc0034382c0, 0x55d471ab61b6, 0xe, 0x55d471aac42b, 0x4, 0xc000090d90, 0x6a, 0x0, ...)
	github.com/kurin/blazer@v0.5.3/base/base.go:392 +0x6e9
github.com/kurin/blazer/base.(*URL).UploadFile(0xc003367e30, 0x55d4720c8c20, 0xc0034382c0, 0x55d4720b0ee0, 0xc000512fc0, 0x2a2, 0xc000aa1b90, 0x62, 0x55d471ac03fa, 0x18, ...)
	github.com/kurin/blazer@v0.5.3/base/base.go:730 +0x570
github.com/kurin/blazer/b2.(*b2URL).uploadFile(0xc00000fab8, 0x55d4720c8c20, 0xc0034382c0, 0x55d4720b0ee0, 0xc000512fc0, 0x2a2, 0xc000aa1b90, 0x62, 0x55d471ac03fa, 0x18, ...)
	github.com/kurin/blazer@v0.5.3/b2/baseline.go:404 +0xe1
github.com/kurin/blazer/b2.(*beURL).uploadFile.func1(0xc000726710, 0xc0007266f8)
	github.com/kurin/blazer@v0.5.3/b2/backend.go:510 +0x1df
github.com/kurin/blazer/b2.withBackoff(0x55d4720c8c20, 0xc0034382c0, 0x55d4720d3080, 0xc0000aecf0, 0xc0007267b8, 0xc0007267d8, 0x20)
	github.com/kurin/blazer@v0.5.3/b2/backend.go:747 +0x4f
github.com/kurin/blazer/b2.(*beURL).uploadFile(0xc00075cc40, 0x55d4720c8c20, 0xc0034382c0, 0x55d4720bb960, 0xc000512fc0, 0x2a2, 0xc000aa1b90, 0x62, 0x55d471ac03fa, 0x18, ...)
	github.com/kurin/blazer@v0.5.3/b2/backend.go:521 +0x15f
github.com/kurin/blazer/b2.(*Writer).simpleWriteFile(0xc000342420, 0x0, 0x0)
	github.com/kurin/blazer@v0.5.3/b2/writer.go:307 +0x362
github.com/kurin/blazer/b2.(*Writer).Close.func1()
	github.com/kurin/blazer@v0.5.3/b2/writer.go:497 +0x251
sync.(*Once).doSlow(0xc0003424cc, 0xc000726a68)
	sync/once.go:66 +0xee
sync.(*Once).Do(...)
	sync/once.go:57
github.com/kurin/blazer/b2.(*Writer).Close(0xc000342420, 0x27a, 0x7fc9957a0388)
	github.com/kurin/blazer@v0.5.3/b2/writer.go:483 +0x8e
github.com/restic/restic/internal/backend/b2.(*b2Backend).Save(0xc000128b80, 0x55d4720c8c20, 0xc003438280, 0x55d471aac66b, 0x4, 0xc000baa200, 0x40, 0x55d4720c4460, 0xc000260480, 0x0, ...)
	github.com/restic/restic/internal/backend/b2/b2.go:216 +0x4ed
github.com/restic/restic/internal/backend.(*RetryBackend).Save.func1(0xc0002604e0, 0xc0002604e0)
	github.com/restic/restic/internal/backend/backend_retry.go:66 +0xfa
github.com/cenkalti/backoff/v4.RetryNotifyWithTimer(0xc000726de8, 0x7fc995b92eb8, 0xc0002604e0, 0xc000726d48, 0x55d4720c3f60, 0xc00000e370, 0x0, 0x0)
	github.com/cenkalti/backoff/v4@v4.0.2/retry.go:52 +0xfa
github.com/cenkalti/backoff/v4.RetryNotify(...)
	github.com/cenkalti/backoff/v4@v4.0.2/retry.go:31
github.com/restic/restic/internal/backend.(*RetryBackend).retry(0xc0001aa040, 0x55d4720c8c20, 0xc000033f40, 0xc000685260, 0x17, 0xc000726de8, 0x17, 0x55d472097220)
	github.com/restic/restic/internal/backend/backend_retry.go:46 +0x1ac
github.com/restic/restic/internal/backend.(*RetryBackend).Save(0xc0001aa040, 0x55d4720c8c20, 0xc000033f40, 0x55d471aac66b, 0x4, 0xc000baa200, 0x40, 0x55d4720c4460, 0xc000260480, 0x0, ...)
	github.com/restic/restic/internal/backend/backend_retry.go:60 +0x1b9
github.com/restic/restic/internal/cache.(*Backend).Save(0xc00069e6f0, 0x55d4720c8c20, 0xc000033f40, 0x55d471aac66b, 0x4, 0xc000baa200, 0x40, 0x55d4720c4460, 0xc000260480, 0xc000678220, ...)
	github.com/restic/restic/internal/cache/backend.go:54 +0x31d
github.com/restic/restic/internal/repository.(*Repository).savePacker(0xc00076ca80, 0x55d4720c8c20, 0xc000033f40, 0x2, 0xc000260460, 0x0, 0x0)
	github.com/restic/restic/internal/repository/packer_manager.go:110 +0x1fc
github.com/restic/restic/internal/repository.(*Repository).FlushPacks(0xc00076ca80, 0x55d4720c8c20, 0xc000033f40, 0x211, 0x313c08f2)
	github.com/restic/restic/internal/repository/repository.go:357 +0xe8
github.com/restic/restic/internal/repository.(*Repository).Flush(0xc00076ca80, 0x55d4720c8c20, 0xc000033f40, 0x0, 0x0)
	github.com/restic/restic/internal/repository/repository.go:331 +0x45
github.com/restic/restic/internal/archiver.(*Archiver).Snapshot(0xc0002001b0, 0x55d4720c8c20, 0xc000033f40, 0xc000443e30, 0x1, 0x1, 0x55d4727d36a0, 0x0, 0x0, 0xc0004cc1d9, ...)
	github.com/restic/restic/internal/archiver/archiver.go:824 +0x35e
main.runBackup(0x0, 0x0, 0x0, 0xc0004b7180, 0x2, 0x2, 0x0, 0x0, 0x0, 0x0, ...)
	github.com/restic/restic/cmd/restic/cmd_backup.go:710 +0x1097
main.glob..func2(0x55d472733880, 0xc0000b4f00, 0x1, 0x8, 0x0, 0x0)
	github.com/restic/restic/cmd/restic/cmd_backup.go:62 +0x182
github.com/spf13/cobra.(*Command).execute(0x55d472733880, 0xc0004ae1c0, 0x8, 0xe, 0x55d472733880, 0xc0004ae1c0)
	github.com/spf13/cobra@v0.0.5/command.go:826 +0x455
github.com/spf13/cobra.(*Command).ExecuteC(0x55d472736800, 0xc000443d80, 0x2, 0x8)
	github.com/spf13/cobra@v0.0.5/command.go:914 +0x2fd
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v0.0.5/command.go:864
main.main()
	github.com/restic/restic/cmd/restic/main.go:98 +0x41

goroutine 18 [chan receive, 917 minutes]:
github.com/restic/restic/internal/restic.init.0.func1.1()
	github.com/restic/restic/internal/restic/lock.go:254 +0xb5
created by github.com/restic/restic/internal/restic.init.0.func1
	github.com/restic/restic/internal/restic/lock.go:251 +0x37

goroutine 33 [syscall, 917 minutes]:
os/signal.signal_recv(0x0)
	runtime/sigqueue.go:147 +0x9e
os/signal.loop()
	os/signal/signal_unix.go:23 +0x24
created by os/signal.Notify.func1
	os/signal/signal.go:127 +0x46

goroutine 5 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000b4300)
	go.opencensus.io@v0.22.4/stats/view/worker.go:276 +0x102
created by go.opencensus.io/stats/view.init.0
	go.opencensus.io@v0.22.4/stats/view/worker.go:34 +0x6a

goroutine 6 [chan receive, 917 minutes]:
main.CleanupHandler(0xc000093680)
	github.com/restic/restic/cmd/restic/cleanup.go:59 +0x4e
created by main.init.0
	github.com/restic/restic/cmd/restic/cleanup.go:21 +0x69

goroutine 7 [select, 862 minutes]:
github.com/restic/restic/internal/ui/termstatus.(*Terminal).runWithoutStatus(0xc000093ce0, 0x55d4720c8c20, 0xc000144180)
	github.com/restic/restic/internal/ui/termstatus/status.go:185 +0x141
github.com/restic/restic/internal/ui/termstatus.(*Terminal).Run(0xc000093ce0, 0x55d4720c8c20, 0xc000144180)
	github.com/restic/restic/internal/ui/termstatus/status.go:95 +0xac
main.glob..func2.1(0x0, 0x0)
	github.com/restic/restic/cmd/restic/cmd_backup.go:60 +0x6f
gopkg.in/tomb%2ev2.(*Tomb).run(0xc0000aafa0, 0xc0004b71e0)
	gopkg.in/tomb.v2@v2.0.0-20161208151619-d5d1b5820637/tomb.go:163 +0x3a
created by gopkg.in/tomb%2ev2.(*Tomb).Go
	gopkg.in/tomb.v2@v2.0.0-20161208151619-d5d1b5820637/tomb.go:159 +0xbc

goroutine 82 [select]:
github.com/restic/restic/internal/ui.(*Backup).Run(0xc000387930, 0x55d4720c8c20, 0xc0034384c0, 0x0, 0x0)
	github.com/restic/restic/internal/ui/backup.go:102 +0x353
main.runBackup.func2(0x0, 0xc0001262a0)
	github.com/restic/restic/cmd/restic/cmd_backup.go:566 +0x86
gopkg.in/tomb%2ev2.(*Tomb).run(0xc0000aaff0, 0xc003367c80)
	gopkg.in/tomb.v2@v2.0.0-20161208151619-d5d1b5820637/tomb.go:163 +0x3a
created by gopkg.in/tomb%2ev2.(*Tomb).Go
	gopkg.in/tomb.v2@v2.0.0-20161208151619-d5d1b5820637/tomb.go:159 +0xbc

goroutine 2261 [select, 4 minutes]:
main.refreshLocks(0x55d4727a7b60, 0xc00034b440)
	github.com/restic/restic/cmd/restic/lock.go:70 +0x1c2
created by main.lockRepository
	github.com/restic/restic/cmd/restic/lock.go:47 +0x269

goroutine 39827 [IO wait]:
internal/poll.runtime_pollWait(0x7fc995b40f18, 0x72, 0xffffffffffffffff)
	runtime/netpoll.go:203 +0x57
internal/poll.(*pollDesc).wait(0xc000128518, 0x72, 0x200, 0x205, 0xffffffffffffffff)
	internal/poll/fd_poll_runtime.go:87 +0x47
internal/poll.(*pollDesc).waitRead(...)
	internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000128500, 0xc0003a2240, 0x205, 0x205, 0x0, 0x0, 0x0)
	internal/poll/fd_unix.go:169 +0x19d
net.(*netFD).Read(0xc000128500, 0xc0003a2240, 0x205, 0x205, 0x203000, 0xc000100e00, 0x7fc9bcc5c7d0)
	net/fd_unix.go:202 +0x51
net.(*conn).Read(0xc0002e8008, 0xc0003a2240, 0x205, 0x205, 0x0, 0x0, 0x0)
	net/net.go:184 +0x90
crypto/tls.(*atLeastReader).Read(0xc000772040, 0xc0003a2240, 0x205, 0x205, 0xc0003a2240, 0x0, 0xc0001919b0)
	crypto/tls/conn.go:760 +0x62
bytes.(*Buffer).ReadFrom(0xc0004d7e58, 0x55d4720b0400, 0xc000772040, 0x55d471191437, 0x55d471f56c80, 0x55d47205dd20)
	bytes/buffer.go:204 +0xb3
crypto/tls.(*Conn).readFromUntil(0xc0004d7c00, 0x55d4720b2860, 0xc0002e8008, 0x5, 0xc0002e8008, 0xc000191a98)
	crypto/tls/conn.go:782 +0xee
crypto/tls.(*Conn).readRecordOrCCS(0xc0004d7c00, 0x100, 0x126, 0x0)
	crypto/tls/conn.go:589 +0x117
crypto/tls.(*Conn).readRecord(...)
	crypto/tls/conn.go:557
crypto/tls.(*Conn).readHandshake(0xc0004d7c00, 0xc00016c016, 0xc00016c000, 0x126, 0x180)
	crypto/tls/conn.go:973 +0x6f
crypto/tls.(*Conn).clientHandshake(0xc0004d7c00, 0x0, 0x0)
	crypto/tls/handshake_client.go:172 +0x27b
crypto/tls.(*Conn).Handshake(0xc0004d7c00, 0x0, 0x0)
	crypto/tls/conn.go:1340 +0xce
net/http.(*persistConn).addTLS.func2(0x0, 0xc0004d7c00, 0xc000642050, 0xc00019a420)
	net/http/transport.go:1512 +0x44
created by net/http.(*persistConn).addTLS
	net/http/transport.go:1508 +0x1ac

goroutine 39786 [chan receive]:
net/http.(*persistConn).addTLS(0xc0005e6120, 0xc0000366c0, 0x1d, 0x0, 0xc0000366de, 0x3)
	net/http/transport.go:1518 +0x1d5
net/http.(*Transport).dialConn(0xc00041de00, 0x55d4720c8c20, 0xc0034382c0, 0x0, 0xc000090d90, 0x5, 0xc0000366c0, 0x21, 0x0, 0xc0005e6120, ...)
	net/http/transport.go:1588 +0x1c5f
net/http.(*Transport).dialConnFor(0xc00041de00, 0xc0001c22c0)
	net/http/transport.go:1424 +0xc8
created by net/http.(*Transport).queueForDial
	net/http/transport.go:1393 +0x400

rax    0xca
rbx    0x55d4727a9740
rcx    0x55d4711ed623
rdx    0x0
rdi    0x55d4727a9888
rsi    0x80
rbp    0x7ffc22012d70
rsp    0x7ffc22012d28
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x3
r13    0x55d4727a8fa0
r14    0x0
r15    0x0
rip    0x55d4711ed621
rflags 0x286
cs     0x33
fs     0x0
gs     0x0

Can anyone shed some insight as to what this might mean?

17

There’s not too much to see in the stack traces. restic tries to upload a pack file (look for b2.(*b2Backend).Save) and apparently tries to connect to some B2 server (crypto/tls.(*Conn).clientHandshake). Further investigation would require a debug build of restic, see restic/CONTRIBUTING.md at master · restic/restic · GitHub for instructions.

18

Thanks Michael,

I’m suspecting that something is happening on the B2 end as this script has been running successfully for a few years.

If nothing turns up on that end, i’ll try to build it locally, and dig in further – just trying to rule out as much as possible before I go down that path.

19

Following up on this quickly… I was able to build restic with the debug option – and was able to reproduce the error.

Here’s what i’m seeing at the tail of the debug log – repeatedly…

2021/07/30 17:55:54 debug/round_tripper_debug.go:87	debug.loggingRoundTripper.RoundTrip	1	RoundTrip() returned error: net/http: TLS handshake timeout
2021/07/30 17:55:55 debug/round_tripper_debug.go:82	debug.loggingRoundTripper.RoundTrip	1	------------  HTTP REQUEST -----------
POST /b2api/v1/b2_upload_file/7d8a6a71770de3f2756e071b/c002_v0001162_t0026 HTTP/1.1
Host: pod-000-1162-18.backblaze.com
User-Agent: blazer/0.5.3
Content-Length: 147
Authorization: 4_002daa17d325e7b0000000005_********_77ae9d_upld__qNgpsV1oG23Kcc978zoxQyjzIE=
Content-Type: application/octet-stream
X-Blazer-Method: b2_upload_file
X-Blazer-Request-Id: 23
X-Bz-Content-Sha1: 3236089fc58280923d301d26b308bafb11b619dd
X-Bz-File-Name: PROJECT_NAME_HERE/locks/2c41c7191ce676fe47d1e61a09601d4ba62eb6393bcdda36683979e1bedb3931
Accept-Encoding: gzip

Any idea what this might be?

G

20

Does the Host change over time? Are you able to connect to that server e.g. using curl? What output does setting the environment variable B2_LOG_LEVEL=2 create?