Fixed, but autoupdate problem? Mac 0.12.21

Support
1

In hindsight, I wish I’d looked more into what happened, but I rushed through it. I found syncthing not responding on one Mac. This is a snipped transcript of what I saw. In a nutshell, its:

  1. three lines looping endlessly in system.log
  2. standard launch (sorry!) of binary yields SIGILL: Illegal instruction, go stuff
  3. my auto-updated syncthing binary doesn’t match a fresh download’s hash
  4. replace just the binary and all is well

Problem solved. Just posting in case I’m not alone in having encountered this. Cheers!

1• Looping log

$ tail -3 /var/log/system.log
Apr  1 14:15:01 host kernel[0]: CODE SIGNING: cs_invalid_page(0x11c000): p=3125[syncthing] final status 0x0, allowing (remove VALID) page
Apr  1 14:15:01 host com.apple.launchd.peruser.502[273] (net.syncthing.syncthing[3125]): Exited with code: 2
Apr  1 14:15:01 host com.apple.launchd.peruser.502[273] (net.syncthing.syncthing): Throttling respawn: Will start in 10 seconds

2• sample run

$ ~/bin/syncthing
[monitor] 14:21:05 INFO: Starting syncthing
[X4W26] 14:21:05 INFO: syncthing v0.12.21 "Beryllium Bedbug" (go1.6 darwin-amd64) jb@apto.nym.se 2016-03-23 08:17:59 UTC
[X4W26] 14:21:05 INFO: My ID: X4W26BS-IPS7I2G-ZZ2LNSQ-ASZUDLY-ACNF2IA-EHTWIZG-TQ3DS33-WQPVVQ4
[X4W26] 14:21:05 INFO: Single thread hash performance is ~146 MB/s
SIGILL: illegal instruction
PC=0xa2004 m=3

goroutine 1 [running]:
runtime.call131072(0x18442d0, 0xc8201760c8, 0x8dbe7c4806af2dbf, 0x1a344b00655b3a67)
        /usr/local/go/src/runtime/asm_amd64.s:484 +0xd4 fp=0xc8202696a0 sp=0xc820269698
github.com/syncthing/syncthing/lib/config.Load(0xc820122b00, 0x3c, 0x8dbe7c4806af2dbf, 0x1a344b00655b3a67, 0x233b0f01489726c0, 0x6b7dd0ee2dc78633, 0x0, 0x0, 0x0)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/lib/config/wrapper.go:88 +0x147 fp=0xc82026a008 sp=0xc8202696a0
main.loadConfig(0x0, 0x0, 0x0)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:912 +0xbd fp=0xc82026a988 sp=0xc82026a008
main.loadOrCreateConfig(0xc8200110e0)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:925 +0x27 fp=0xc82026ac48 sp=0xc82026a988
main.syncthingMain(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x8066a8, 0x1, 0x0, 0x0, ...)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:577 +0xe72 fp=0xc82026bd00 sp=0xc82026ac48
main.main()
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:364 +0x95d fp=0xc82026bf30 sp=0xc82026bd00
runtime.main()
        /usr/local/go/src/runtime/proc.go:188 +0x2b0 fp=0xc82026bf80 sp=0xc82026bf30
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc82026bf88 sp=0xc82026bf80

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1

goroutine 5 [sleep]:
time.Sleep(0x1dcd6500)
        /usr/local/go/src/runtime/time.go:59 +0xf9
github.com/syncthing/syncthing/lib/dialer.init.1.func2()
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/lib/dialer/internal.go:46 +0x24
created by github.com/syncthing/syncthing/lib/dialer.init.1
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/lib/dialer/internal.go:48 +0x291

goroutine 18 [syscall]:
os/signal.signal_recv(0x0)
        /usr/local/go/src/runtime/sigqueue.go:116 +0x132
os/signal.loop()
        /usr/local/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
        /usr/local/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 19 [chan receive]:
main.trackCPUUsage()
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/gui_unix.go:24 +0xe7
created by main.init.3
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/gui_unix.go:17 +0x2b

goroutine 20 [select, locked to thread]:
runtime.gopark(0x967ae0, 0xc820023728, 0x80ee88, 0x6, 0x18, 0x2)
        /usr/local/go/src/runtime/proc.go:262 +0x163
runtime.selectgoImpl(0xc820023728, 0x0, 0x18)
        /usr/local/go/src/runtime/select.go:392 +0xa67
runtime.selectgo(0xc820023728)
        /usr/local/go/src/runtime/select.go:215 +0x12
runtime.ensureSigM.func1()
        /usr/local/go/src/runtime/signal1_unix.go:279 +0x32c
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1

goroutine 21 [chan receive]:
main.setupSignalHandling.func1(0xc82017a480)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:879 +0x36
created by main.setupSignalHandling
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:881 +0x155

goroutine 22 [chan receive]:
main.setupSignalHandling.func2(0xc82017a600)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:889 +0x36
created by main.setupSignalHandling
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:891 +0x2c6

goroutine 23 [select]:
github.com/thejerf/suture.(*Supervisor).Serve(0xc82017c820)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/Godeps/_workspace/src/github.com/thejerf/suture/suture.go:441 +0x1080
created by github.com/thejerf/suture.(*Supervisor).ServeBackground
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/Godeps/_workspace/src/github.com/thejerf/suture/suture.go:400 +0x39

goroutine 24 [select]:
github.com/syncthing/syncthing/lib/events.(*Subscription).Poll(0xc820172380, 0xdf8475800, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/lib/events/events.go:210 +0x4dd
github.com/syncthing/syncthing/lib/events.(*BufferedSubscription).pollingLoop(0xc8201743c0)
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/lib/events/events.go:252 +0x45
created by github.com/syncthing/syncthing/lib/events.NewBufferedSubscription
        /Users/jb/jenkins/workspace/syncthing-release-mac/src/github.com/syncthing/syncthing/lib/events/events.go:246 +0x262

rax    0xc8202ec080
rbx    0x0
rcx    0x1
rdx    0x7
rdi    0xc820269988
rsi    0xc8202696d0
rbp    0xc820186240
rsp    0xc820269698
r8     0x20
r9     0xc820268f20
r10    0xc8202f0560
r11    0x0
r12    0x2
r13    0x964858
r14    0x1
r15    0x8
rip    0xa2004
rflags 0x10202
cs     0x2b
fs     0x0
gs     0x750000
[monitor] 14:21:05 INFO: Syncthing exited: exit status 2
[monitor] 14:21:06 INFO: Starting syncthing
[X4W26] 14:21:06 INFO: syncthing v0.12.21 "Beryllium Bedbug" (go1.6 darwin-amd64) jb@apto.nym.se 2016-03-23 08:17:59 UTC
[X4W26] 14:21:06 INFO: My ID: X4W26BS-IPS7I2G-ZZ2LNSQ-ASZUDLY-ACNF2IA-EHTWIZG-TQ3DS33-WQPVVQ4
[X4W26] 14:21:07 INFO: Single thread hash performance is ~153 MB/s
SIGILL: illegal instruction
^C

3• and 4• hashes differ, replacement works

$ md5 -q ~/bin/syncthing
0c9c8c2d65b71d5f0eed903d9496e44f
$ md5 -q ~/Downloads/syncthing-macosx-amd64-v0.12.21/syncthing
450722b71c0c31a11ac7bde0eebe3d6e

$ mv ~/Downloads/syncthing-macosx-amd64-v0.12.21/syncthing ~/bin
~/bin/syncthing
[monitor] 15:12:21 INFO: Starting syncthing
[X4W26] 15:12:21 INFO: syncthing v0.12.21 "Beryllium Bedbug" (go1.6 darwin-amd64) jb@apto.nym.se 2016-03-23 08:26:04 UTC
[X4W26] 15:12:21 INFO: My ID: X4W26BS-IPS7I2G-ZZ2LNSQ-ASZUDLY-ACNF2IA-EHTWIZG-TQ3DS33-WQPVVQ4
[X4W26] 15:12:21 INFO: Single thread hash performance is ~154 MB/s
[X4W26] 15:12:21 OK: Ready to synchronize <snipped. now working well...>
2

Weird. Something seems to have broke the binary. We check the signature during upgrade, but it could have been corrupted during the subsequent write or something perhaps.

3

I wonder if we should do our own signature checks.

4

We do. We even do it by reading the temp file we created, before promoting it to being the actual binary. So it seems to me this should not happen unless there is actual disk or memory corruption going on.

5

I mean upon startup

6

Ah. Sure, could do that.

7

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.