os/exec: fatal error - unlock of unlocked lock - on arm5 platform #13615

g-johnson · 2015-12-14T20:41:57Z

A fatal error is consistently being generated by the exec.Output() function on the arm platform. The function is being used to call a python script that returns a single line of text.
The function will intermittently fail after 5 to 200 calls with an "unlock of unlocked lock" error.
Using golang version 1.5.2.
The executable was cross-compiled on a Linux 32-bit VM for arm5. I have reduced the failure to the segment of code below.
Any suggestions would be much appreciated.

package main

import (
    "fmt"
    "os/exec"
    "time"
)

func main() {

    ticker := time.NewTicker(time.Millisecond * 200)

    for {
        select {

        case <-ticker.C:

            temp := GetBoardTemp()

            fmt.Println("Temp: ", temp)
        }
    }
}

func GetBoardTemp() string {

    cmd := exec.Command("boardtemp")

    tempOut, _ := cmd.Output()       // <-- intermittent fatal error on this line

    return string(tempOut)
}

The error output:

fatal error: unlock of unlocked lock

runtime stack:
runtime.throw(0x1253d0, 0x17)
        /home/lab/go/src/runtime/panic.go:527 +0x78
runtime.unlock(0x1a9358)
        /home/lab/go/src/runtime/lock_futex.go:105 +0x54
runtime.atomicload64.func1()
        /home/lab/go/src/runtime/atomic_arm.go:133 +0x100
runtime.systemstack(0x1032ff50)
        /home/lab/go/src/runtime/asm_arm.s:256 +0xa8

goroutine 1 [runnable]:
syscall.Syscall(0x6, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/lab/go/src/syscall/asm_linux_arm.s:17 +0x8
syscall.Close(0x9, 0x0, 0x0)
        /home/lab/go/src/syscall/zsyscall_linux_arm.go:296 +0x44
syscall.forkExec(0x10310790, 0xe, 0x1030a2d8, 0x1, 0x1, 0x10331d7c, 0x4f3f, 0x0, 0x0)
        /home/lab/go/src/syscall/exec_unix.go:201 +0x3cc
syscall.StartProcess(0x10310790, 0xe, 0x1030a2d8, 0x1, 0x1, 0x10331d7c, 0x2, 0x4, 0x0, 0x0)
        /home/lab/go/src/syscall/exec_unix.go:240 +0x64
os.startProcess(0x10310790, 0xe, 0x1030a2d8, 0x1, 0x1, 0x10331ea4, 0x1030cfc0, 0x0, 0x0)
        /home/lab/go/src/os/exec_posix.go:45 +0x388
os.StartProcess(0x10310790, 0xe, 0x1030a2d8, 0x1, 0x1, 0x10331ea4, 0x0, 0x0, 0x0)
        /home/lab/go/src/os/doc.go:24 +0x54
os/exec.(*Cmd).Start(0x1034e320, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:328 +0x698
os/exec.(*Cmd).Run(0x1034e320, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:255 +0x28
os/exec.(*Cmd).Output(0x1034e320, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:408 +0x188
main.GetBoardTemp(0x0, 0x0)
        /home/lab/armLockTest/src/main/locktest.go:29 +0x4c
main.main()
        /home/lab/armLockTest/src/main/locktest.go:18 +0x70

The text was updated successfully, but these errors were encountered:

bradfitz · 2015-12-14T20:56:18Z

Hm, my first guess would be an unaligned 64-bit atomic access, but sync.Once (as used by os/exec and syscall.ForkLock) seem to only contain 32-bit values. WaitGroup does 64-bit loads (as seen in the systemstack trace), but I don't see any use of WaitGroup in StartProcess or os/exec.

What hardware is this? And kernel distro/kernel might be relevant.

/cc @ianlancetaylor @minux

g-johnson · 2015-12-14T21:33:07Z

Thank you for your prompt reply. Per you query:

/proc/cpuinfo

Processor       : ARM926EJ-S rev 5 (v5l)
BogoMIPS        : 226.91
Features        : swp half thumb fastmult edsp java
CPU implementer : 0x41
CPU architecture: 5TEJ
CPU variant     : 0x0
CPU part        : 0x926
CPU revision    : 5
Hardware        : DaVinci DA850/OMAP-L138/AM18xx EVM
Revision        : 0000

/proc/version

Linux version 2.6.33-rc4 (lab@lab-desktop) (gcc version 4.3.3 (Sourcery G++ Lite 2009q1-203) ) #42 PREEMPT Tue Mar 25 18:50:48 EDT 2014

ianlancetaylor · 2015-12-14T22:21:34Z

Please set the environment variable GOTRACEBACK=2, run the program, and attach the resulting stack dump. Thanks.

davecheney · 2015-12-14T22:25:35Z

Can you check /proc/cpu/alignment (sorry from memory) and make sure there
are no alignment errors,the numbers should be zero for user space code, and
it might be worthwhile setting the kernel to terminate the process on
alignment errors.

On Tue, 15 Dec 2015, 09:21 Ian Lance Taylor notifications@github.com
wrote:

Please set the environment variable GOTRACEBACK=2, run the program, and
attach the resulting stack dump. Thanks.

—
Reply to this email directly or view it on GitHub
#13615 (comment).

g-johnson · 2015-12-15T13:33:27Z

After setting GOTRACEBACK=2 several test runs were made and all failed consistently with two different error messages. The "unlock of unlocked" which I initially reported and a less common "unexpected signal during runtime execution".

fatal error: unlock of unlocked lock

runtime stack:
runtime.throw(0x1253d0, 0x17)
        /home/lab/go/src/runtime/panic.go:527 +0x78 fp=0x1032ff14 sp=0x1032ff08
runtime.unlock(0x1a9358)
        /home/lab/go/src/runtime/lock_futex.go:105 +0x54 fp=0x1032ff2c sp=0x1032ff14
runtime.atomicload64.func1()
        /home/lab/go/src/runtime/atomic_arm.go:133 +0x100 fp=0x1032ff3c sp=0x1032ff2c
runtime.systemstack(0x1032ff50)
        /home/lab/go/src/runtime/asm_arm.s:256 +0xa8 fp=0x1032ff40 sp=0x1032ff3c

goroutine 1 [runnable]:
syscall.Syscall(0x6, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/lab/go/src/syscall/asm_linux_arm.s:17 +0x8 fp=0x10331c30 sp=0x10331c2c
syscall.Close(0x9, 0x0, 0x0)
        /home/lab/go/src/syscall/zsyscall_linux_arm.go:296 +0x44 fp=0x10331c50 sp=0x10331c30
syscall.forkExec(0x10310150, 0xe, 0x1030a130, 0x1, 0x1, 0x10331d7c, 0x25ab, 0x0, 0x0)
        /home/lab/go/src/syscall/exec_unix.go:201 +0x3cc fp=0x10331ce0 sp=0x10331c50
syscall.StartProcess(0x10310150, 0xe, 0x1030a130, 0x1, 0x1, 0x10331d7c, 0x2, 0x4, 0x0, 0x0)
        /home/lab/go/src/syscall/exec_unix.go:240 +0x64 fp=0x10331d08 sp=0x10331ce0
os.startProcess(0x10310150, 0xe, 0x1030a130, 0x1, 0x1, 0x10331ea4, 0x1030c100, 0x0, 0x0)
        /home/lab/go/src/os/exec_posix.go:45 +0x388 fp=0x10331da0 sp=0x10331d08
os.StartProcess(0x10310150, 0xe, 0x1030a130, 0x1, 0x1, 0x10331ea4, 0x0, 0x0, 0x0)
        /home/lab/go/src/os/doc.go:24 +0x54 fp=0x10331dc8 sp=0x10331da0
os/exec.(*Cmd).Start(0x10350000, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:328 +0x698 fp=0x10331ec8 sp=0x10331dc8
os/exec.(*Cmd).Run(0x10350000, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:255 +0x28 fp=0x10331ee0 sp=0x10331ec8
os/exec.(*Cmd).Output(0x10350000, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:408 +0x188 fp=0x10331f18 sp=0x10331ee0
main.GetBoardTemp(0x0, 0x0)
        /home/lab/armLockTest/src/main/locktest.go:29 +0x4c fp=0x10331f40 sp=0x10331f18
main.main()
        /home/lab/armLockTest/src/main/locktest.go:18 +0x70 fp=0x10331f9c sp=0x10331f40
runtime.main()
        /home/lab/go/src/runtime/proc.go:111 +0x2b4 fp=0x10331fc4 sp=0x10331f9c
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x10331fc4 sp=0x10331fc4

goroutine 2 [force gc (idle)]:
runtime.gopark(0x13da9c, 0x194b80, 0x11ee90, 0xf, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031c7a8 sp=0x1031c794
runtime.goparkunlock(0x194b80, 0x11ee90, 0xf, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031c7c4 sp=0x1031c7a8
runtime.forcegchelper()
        /home/lab/go/src/runtime/proc.go:152 +0xa8 fp=0x1031c7dc sp=0x1031c7c4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031c7dc sp=0x1031c7dc
created by runtime.init.4
        /home/lab/go/src/runtime/proc.go:141 +0x24

goroutine 3 [GC sweep wait]:
runtime.gopark(0x13da9c, 0x194c10, 0x11e670, 0xd, 0x2de14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031cf9c sp=0x1031cf88
runtime.goparkunlock(0x194c10, 0x11e670, 0xd, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031cfb8 sp=0x1031cf9c
runtime.bgsweep(0x1033a000)
        /home/lab/go/src/runtime/mgcsweep.go:51 +0x90 fp=0x1031cfd4 sp=0x1031cfb8
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031cfd4 sp=0x1031cfd4
created by runtime.gcenable
        /home/lab/go/src/runtime/mgc.go:206 +0x4c

goroutine 4 [finalizer wait]:
runtime.gopark(0x13da9c, 0x1a7d5c, 0x11ede0, 0xe, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031d788 sp=0x1031d774
runtime.goparkunlock(0x1a7d5c, 0x11ede0, 0xe, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031d7a4 sp=0x1031d788
runtime.runfinq()
        /home/lab/go/src/runtime/mfinal.go:154 +0xa4 fp=0x1031d7dc sp=0x1031d7a4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031d7dc sp=0x1031d7dc
created by runtime.createfing
        /home/lab/go/src/runtime/mfinal.go:135 +0x5c

goroutine 5 [syscall]:
runtime.notetsleepg(0x194c74, 0xbce1a87, 0x0, 0x0)
        /home/lab/go/src/runtime/lock_futex.go:202 +0x4c fp=0x1031df88 sp=0x1031df70
runtime.timerproc()
        /home/lab/go/src/runtime/time.go:209 +0x11c fp=0x1031dfdc sp=0x1031df88
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031dfdc sp=0x1031dfdc
created by runtime.addtimerLocked
        /home/lab/go/src/runtime/time.go:116 +0x1c4

fatal error: unexpected signal during runtime execution
[signal 0xb code=0x1 addr=0xf8475800 pc=0x64df8]

runtime stack:
runtime.throw(0x12eb80, 0x2a)
        /home/lab/go/src/runtime/panic.go:527 +0x78 fp=0x1032fefc sp=0x1032fef0
runtime.sigpanic()
        /home/lab/go/src/runtime/sigpanic_unix.go:12 +0x44 fp=0x1032ff28 sp=0x1032fefc
runtime.atomicload64.func1()
        /home/lab/go/src/runtime/atomic_arm.go:132 +0x8c fp=0x1032ff3c sp=0x1032ff2c

goroutine 1 [running]:
        goroutine running on other thread; stack unavailable

goroutine 2 [force gc (idle)]:
runtime.gopark(0x13da9c, 0x194b80, 0x11ee90, 0xf, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031c7a8 sp=0x1031c794
runtime.goparkunlock(0x194b80, 0x11ee90, 0xf, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031c7c4 sp=0x1031c7a8
runtime.forcegchelper()
        /home/lab/go/src/runtime/proc.go:152 +0xa8 fp=0x1031c7dc sp=0x1031c7c4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031c7dc sp=0x1031c7dc
created by runtime.init.4
        /home/lab/go/src/runtime/proc.go:141 +0x24

goroutine 3 [GC sweep wait]:
runtime.gopark(0x13da9c, 0x194c10, 0x11e670, 0xd, 0x66414, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031cf9c sp=0x1031cf88
runtime.goparkunlock(0x194c10, 0x11e670, 0xd, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031cfb8 sp=0x1031cf9c
runtime.bgsweep(0x1033a000)
        /home/lab/go/src/runtime/mgcsweep.go:67 +0x13c fp=0x1031cfd4 sp=0x1031cfb8
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031cfd4 sp=0x1031cfd4
created by runtime.gcenable
        /home/lab/go/src/runtime/mgc.go:206 +0x4c

goroutine 4 [finalizer wait]:
runtime.gopark(0x13da9c, 0x1a7d5c, 0x11ede0, 0xe, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031d788 sp=0x1031d774
runtime.goparkunlock(0x1a7d5c, 0x11ede0, 0xe, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031d7a4 sp=0x1031d788
runtime.runfinq()
        /home/lab/go/src/runtime/mfinal.go:154 +0xa4 fp=0x1031d7dc sp=0x1031d7a4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031d7dc sp=0x1031d7dc
created by runtime.createfing
        /home/lab/go/src/runtime/mfinal.go:135 +0x5c

goroutine 5 [syscall]:
runtime.notetsleepg(0x194c74, 0xbe2c344, 0x0, 0x0)
        /home/lab/go/src/runtime/lock_futex.go:202 +0x4c fp=0x1031df88 sp=0x1031df70
runtime.timerproc()
        /home/lab/go/src/runtime/time.go:209 +0x11c fp=0x1031dfdc sp=0x1031df88
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031dfdc sp=0x1031dfdc
created by runtime.addtimerLocked
        /home/lab/go/src/runtime/time.go:116 +0x1c4

goroutine 8 [Concurrent GC wait]:
runtime.gopark(0x13da9c, 0x194c00, 0x120ba0, 0x12, 0x1031ed14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031efa8 sp=0x1031ef94
runtime.goparkunlock(0x194c00, 0x120ba0, 0x12, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031efc4 sp=0x1031efa8
runtime.backgroundgc()
        /home/lab/go/src/runtime/mgc.go:900 +0x78 fp=0x1031efdc sp=0x1031efc4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031efdc sp=0x1031efdc
created by runtime.startGC
        /home/lab/go/src/runtime/mgc.go:870 +0x178

goroutine 9 [mark worker (idle)]:
runtime.gopark(0x13d9fc, 0x10320b00, 0x122568, 0x12, 0x14, 0x0)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031f794 sp=0x1031f780
runtime.gcBgMarkWorker(0x10316a00)
        /home/lab/go/src/runtime/mgc.go:1289 +0xd8 fp=0x1031f7d4 sp=0x1031f794
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031f7d4 sp=0x1031f7d4
created by runtime.gcBgMarkStartWorkers
        /home/lab/go/src/runtime/mgc.go:1239 +0x84

g-johnson · 2015-12-15T13:43:06Z

After a clean boot of the system, the below cpu/alignment report was printed. After several test runs that all resulted in failure, the alignment report still reported zero errors (no change). I modified the User fault setting per your suggestion to "5" (report bus error) and ran the above reported tests under that setting.

cat /proc/cpu/alignment

User:           0
System:         0
Skipped:        0
Half:           0
Word:           0
DWord:          0
Multi:          0
User faults:    3 (fixup+warn)

g-johnson · 2015-12-15T13:59:06Z

Followup: After several dozen test runs that all ended in panic, one test run was encountered that resulted in an alignment error.

fatal error: unexpected signal during runtime execution
[signal 0x7 code=0x80 addr=0x0 pc=0x64df8]

runtime stack:
runtime.throw(0x12eb80, 0x2a)
        /home/lab/go/src/runtime/panic.go:527 +0x78 fp=0x1032fefc sp=0x1032fef0
runtime.sigpanic()
        /home/lab/go/src/runtime/sigpanic_unix.go:12 +0x44 fp=0x1032ff28 sp=0x1032fefc
runtime.atomicload64.func1()
        /home/lab/go/src/runtime/atomic_arm.go:132 +0x8c fp=0x1032ff3c sp=0x1032ff2c
runtime.systemstack(0x236433a2)
        /home/lab/go/src/runtime/asm_arm.s:256 +0xa8 fp=0x1032ff40 sp=0x1032ff3c
runtime.atomicload64(0x1a9668, 0x218, 0x0)
        /home/lab/go/src/runtime/atomic_arm.go:134 +0x40 fp=0x1032ff5c sp=0x1032ff40

goroutine 1 [runnable]:
syscall.Syscall(0x3, 0x8, 0x1032bc94, 0x4, 0x0, 0x0, 0x0)
        /home/lab/go/src/syscall/asm_linux_arm.s:17 +0x8 fp=0x1032bc30 sp=0x1032bc2c
syscall.readlen(0x8, 0x1032bc94, 0x4, 0x2, 0x0, 0x0)
        /home/lab/go/src/syscall/zsyscall_linux_arm.go:1085 +0x4c fp=0x1032bc50 sp=0x1032bc30
syscall.forkExec(0x1044c3a0, 0xe, 0x1040d9c8, 0x1, 0x1, 0x1032bd7c, 0x3020, 0x0, 0x0)
        /home/lab/go/src/syscall/exec_unix.go:202 +0x3e8 fp=0x1032bce0 sp=0x1032bc50
syscall.StartProcess(0x1044c3a0, 0xe, 0x1040d9c8, 0x1, 0x1, 0x1032bd7c, 0x2, 0x4, 0x0, 0x0)
        /home/lab/go/src/syscall/exec_unix.go:240 +0x64 fp=0x1032bd08 sp=0x1032bce0
os.startProcess(0x1044c3a0, 0xe, 0x1040d9c8, 0x1, 0x1, 0x1032bea4, 0x10430e00, 0x0, 0x0)
        /home/lab/go/src/os/exec_posix.go:45 +0x388 fp=0x1032bda0 sp=0x1032bd08
os.StartProcess(0x1044c3a0, 0xe, 0x1040d9c8, 0x1, 0x1, 0x1032bea4, 0x0, 0x0, 0x0)
        /home/lab/go/src/os/doc.go:24 +0x54 fp=0x1032bdc8 sp=0x1032bda0
os/exec.(*Cmd).Start(0x10442960, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:328 +0x698 fp=0x1032bec8 sp=0x1032bdc8
os/exec.(*Cmd).Run(0x10442960, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:255 +0x28 fp=0x1032bee0 sp=0x1032bec8
os/exec.(*Cmd).Output(0x10442960, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/lab/go/src/os/exec/exec.go:408 +0x188 fp=0x1032bf18 sp=0x1032bee0
main.GetBoardTemp(0x0, 0x0)
        /home/lab/armLockTest/src/main/locktest.go:29 +0x4c fp=0x1032bf40 sp=0x1032bf18
main.main()
        /home/lab/armLockTest/src/main/locktest.go:18 +0x70 fp=0x1032bf9c sp=0x1032bf40
runtime.main()
        /home/lab/go/src/runtime/proc.go:111 +0x2b4 fp=0x1032bfc4 sp=0x1032bf9c
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1032bfc4 sp=0x1032bfc4

goroutine 2 [force gc (idle)]:
runtime.gopark(0x13da9c, 0x194b80, 0x11ee90, 0xf, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031c7a8 sp=0x1031c794
runtime.goparkunlock(0x194b80, 0x11ee90, 0xf, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031c7c4 sp=0x1031c7a8
runtime.forcegchelper()
        /home/lab/go/src/runtime/proc.go:152 +0xa8 fp=0x1031c7dc sp=0x1031c7c4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031c7dc sp=0x1031c7dc
created by runtime.init.4
        /home/lab/go/src/runtime/proc.go:141 +0x24

goroutine 3 [GC sweep wait]:
runtime.gopark(0x13da9c, 0x194c10, 0x11e670, 0xd, 0x2de14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031cf9c sp=0x1031cf88
runtime.goparkunlock(0x194c10, 0x11e670, 0xd, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031cfb8 sp=0x1031cf9c
runtime.bgsweep(0x10342000)
        /home/lab/go/src/runtime/mgcsweep.go:51 +0x90 fp=0x1031cfd4 sp=0x1031cfb8
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031cfd4 sp=0x1031cfd4
created by runtime.gcenable
        /home/lab/go/src/runtime/mgc.go:206 +0x4c

goroutine 4 [finalizer wait]:
runtime.gopark(0x13da9c, 0x1a7d5c, 0x11ede0, 0xe, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:185 +0x148 fp=0x1031d788 sp=0x1031d774
runtime.goparkunlock(0x1a7d5c, 0x11ede0, 0xe, 0x14, 0x1)
        /home/lab/go/src/runtime/proc.go:191 +0x44 fp=0x1031d7a4 sp=0x1031d788
runtime.runfinq()
        /home/lab/go/src/runtime/mfinal.go:154 +0xa4 fp=0x1031d7dc sp=0x1031d7a4
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031d7dc sp=0x1031d7dc
created by runtime.createfing
        /home/lab/go/src/runtime/mfinal.go:135 +0x5c

goroutine 5 [syscall]:
runtime.notetsleepg(0x194c74, 0xbe1dbd2, 0x0, 0x0)
        /home/lab/go/src/runtime/lock_futex.go:202 +0x4c fp=0x1031df88 sp=0x1031df70
runtime.timerproc()
        /home/lab/go/src/runtime/time.go:209 +0x11c fp=0x1031dfdc sp=0x1031df88
runtime.goexit()
        /home/lab/go/src/runtime/asm_arm.s:1036 +0x4 fp=0x1031dfdc sp=0x1031dfdc
created by runtime.addtimerLocked
        /home/lab/go/src/runtime/time.go:116 +0x1c4

cat /proc/cpu/alignment

User:           1
System:         0
Skipped:        0
Half:           0
Word:           0
DWord:          0
Multi:          0
User faults:    5 (signal+warn)

davecheney · 2015-12-15T19:13:14Z

Thanks for confirming, it's good to know that alignment errors haven't crept back into code generation.

On 16 Dec 2015, at 00:43, g-johnson notifications@github.com wrote:

After a clean boot of the system, the below cpu/alignment report was printed. After several test runs that all resulted in failure, the alignment report still reported zero errors (no change). I modified the User fault setting per your suggestion to "5" (report bus error) and ran the above reported tests under that setting.

cat /proc/cpu/alignment

User: 0
System: 0
Skipped: 0
Half: 0
Word: 0
DWord: 0
Multi: 0
User faults: 3 (fixup+warn)
—
Reply to this email directly or view it on GitHub.

minux · 2015-12-15T20:52:43Z

It still sounds like memory corruption bugs. The address given to atomicload64 is aligned correctly.

g-johnson · 2015-12-15T21:16:21Z

The test code was run on another hardware platform to confirm that it is not a hardware problem. The code fails in the same manner on alternate hardware.

minux · 2015-12-15T22:22:55Z

Do you have gdb (or gdbserver) on the platform? I'd like to catch the SIGBUS under gdb and see exact which instruction triggers it and the address that triggers it. The address in the provided stack trace is perfectly aligned, and the kernel complains that the faulting address is 0, which doesn't make sense. Either the runtime systemstack mechanism is subtly wrong or something else is happening here. If you don't have gdb, at least run the program with GC disabled and see if that helps. (set GOGC=off) Also note that the kernel version (2.6.33) is a little old. If the unlock of unlocked mutex panic happens very frequently, it might well be a kernel futex bug.

g-johnson · 2015-12-16T22:01:24Z

Testing with gdb apparently causes enough of a environment change such that the “unexpected signal” error does not occur easily or at all. It is easy to reproduce the “unlock of unlocked lock” error, but gdb does not provide any additional debugging information about the failure (unless I am missing something).

Looking into getting a more current version of embedded Linux to test if that might be the source of the problem. However the platform has considerable code written and tested to 2.6.33 and upgrading may not be an option regardless. Will advise shortly.

g-johnson · 2015-12-18T19:55:36Z

Am unable to upgrade the Linux version (2.6.33-rc4) on the target platform due to legacy issues. The same code when run on other Linux versions (different platform) works flawlessly.
There are documented changes to address futex issues on Linux version 2.6.33-rc7. At this point it seems most likely that Linux is the source of the problem. However it seems very odd that only the os/exec function is affected.
There is a workaround to avoid using the os/exec function on the target application and that will have be utilized until such time as the root cause is found.
Thank you all for your prompt, courteous and knowledgeable replies.

ianlancetaylor changed the title ~~Fatal error - unlock of unlocked lock - on arm5 platform~~ os/exec: fatal error - unlock of unlocked lock - on arm5 platform Dec 14, 2015

g-johnson closed this as completed Dec 22, 2015

golang locked and limited conversation to collaborators Dec 29, 2016

gopherbot added the FrozenDueToAge label Dec 29, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

os/exec: fatal error - unlock of unlocked lock - on arm5 platform #13615

os/exec: fatal error - unlock of unlocked lock - on arm5 platform #13615

g-johnson commented Dec 14, 2015

bradfitz commented Dec 14, 2015

g-johnson commented Dec 14, 2015

ianlancetaylor commented Dec 14, 2015

davecheney commented Dec 14, 2015

g-johnson commented Dec 15, 2015

g-johnson commented Dec 15, 2015

g-johnson commented Dec 15, 2015

davecheney commented Dec 15, 2015

minux commented Dec 15, 2015 via email

g-johnson commented Dec 15, 2015

minux commented Dec 15, 2015 via email

g-johnson commented Dec 16, 2015

g-johnson commented Dec 18, 2015

os/exec: fatal error - unlock of unlocked lock - on arm5 platform #13615

os/exec: fatal error - unlock of unlocked lock - on arm5 platform #13615

Comments

g-johnson commented Dec 14, 2015

bradfitz commented Dec 14, 2015

g-johnson commented Dec 14, 2015

ianlancetaylor commented Dec 14, 2015

davecheney commented Dec 14, 2015

g-johnson commented Dec 15, 2015

g-johnson commented Dec 15, 2015

g-johnson commented Dec 15, 2015

davecheney commented Dec 15, 2015

minux commented Dec 15, 2015 via email

g-johnson commented Dec 15, 2015

minux commented Dec 15, 2015 via email

g-johnson commented Dec 16, 2015

g-johnson commented Dec 18, 2015