go-qml / qml

QML support for the Go language
Other
1.96k stars 189 forks source link

Mac OS bug: is only safe to invoke on the main thread #66

Closed ablegao closed 9 years ago

ablegao commented 10 years ago

mac os 10.9.3 QT 5.2.1

github.com/go-qml/qml/examples/customtype

2014-05-23 01:41:40.054 customtype[44170:1b03] *\ Assertion failure in +[NSUndoManager _endTopLevelGroupings], /SourceCache/Foundation/Foundation-1056.13/Misc.subproj/NSUndoManager.m:328 2014-05-23 01:41:40.056 customtype[44170:1b03] +[NSUndoManager(NSInternal) _endTopLevelGroupings] is only safe to invoke on the main thread. 2014-05-23 01:41:40.065 customtype[44170:1b03](0 CoreFoundation 0x00007fff96fb925c __exceptionPreprocess + 172 1 libobjc.A.dylib 0x00007fff93a99e75 objc_exception_throw + 43 2 CoreFoundation 0x00007fff96fb9038 +[NSException raise:format:arguments:] + 104 3 Foundation 0x00007fff96b5cd41 -[NSAssertionHandler handleFailureInMethod:object:file:lineNumber:description:] + 189 4 Foundation 0x00007fff96ac728c +[NSUndoManager%28NSPrivate%29 _endTopLevelGroupings] + 156 5 AppKit 0x00007fff957ffa43 -[NSApplication run] + 688 6 libqcocoa.dylib 0x0000000007db95a5 _ZN21QCocoaEventDispatcher13processEventsE6QFlagsIN10QEventLoop17ProcessEventsFlagEE + 2149 7 QtCore 0x0000000005a3345d _ZN10QEventLoop4execE6QFlagsINS_17ProcessEventsFlagEE + 397 8 QtCore 0x0000000005a362e7 _ZN16QCoreApplication4execEv + 359 9 customtype 0x0000000004079c61 runtime.asmcgocall + 97)

niemeyer commented 10 years ago

Yeah, there's a new API coming in v1, under the tag v1-dev in the repository (needs manualy git checkout). What's still to be decided is how to make this work with "go test". I have a hack in place there which should make it work, but I haven't had anyone digging through in detail to see how well it works in practice. If you have the time, I'd really appreciate some input on it.

ablegao commented 10 years ago

en ..  why?

gopkg.in/qml.v1/examples/reparent

./reparent.go:17: undefined: qml.Init

gopkg.in/qml.v1/examples/modelview/delegate

./delegate.go:20: undefined: qml.Init

--  Able Gao 高恩博 | 13488828861 | twitter.com/ablegao | weibo.com/ablegao | ablegao.com | weixin:ablegao1

开启 2014年5月23日 at 上午2:05:24, Gustavo Niemeyer (notifications@github.com) 写:

Yeah, there's a new API coming in v1, under the tag v1-dev in the repository (needs manualy git checkout). What's still to be decided is how to make this work with "go test". I have a hack in place there which should make it work, but I haven't had anyone digging through in detail to see how well it works in practice. If you have the time, I'd really appreciate some input on it.

— Reply to this email directly or view it on GitHub.

niemeyer commented 10 years ago

Not all examples were ported yet. If you feel uneasy with the in-development branch, that's totally okay. We can wait until somebody else has the chance to have a look at it.

quarnster commented 10 years ago

FWIW:

20:25 ~/code/go/src/gopkg.in/qml.v1 $ go test -v
=== RUN Test

----------------------------------------------------------------------
FAIL: qml_test.go:1181: S.TestTable

----- Running table test 0: Read a context variable and its fields -----
[LOG] 36.85478 file.qml:5: String is <content>
[LOG] 36.85478 file.qml:6: Int is 42
[LOG] 36.85478 file.qml:7: Any is undefined
----- Running table test 1: Read a nested field via a value (not pointer) in an interface -----
[LOG] 36.85478 file.qml:3: String is <content>
----- Running table test 2: Read a native property -----
----- Running table test 3: Read object properties -----
----- Running table test 4: Lowercasing of object properties -----
[LOG] 36.85478 file.qml:3: Names are <a> <b> <c> <d>
----- Running table test 5: No access to private fields -----
[LOG] 36.85478 file.qml:3: Private is undefined
----- Running table test 6: Set a custom property -----
[LOG] 36.85478 file.qml:6: file:////Users/quarnster/code/go/src/gopkg.in/qml.v1/file.qml:6: TypeError: Cannot read property 'stringValue' of null
[LOG] 36.85478 file.qml:6: String is <content>
[LOG] 36.85478 file.qml:7: Width is 300
[LOG] 36.85478 file.qml:8: Height is 200
----- Running table test 7: Read and set a QUrl property -----
----- Running table test 8: Read and set a QColor property -----
----- Running table test 9: Read and set a QColor property from a Go field -----
[LOG] 36.85478 file.qml:3: #102040
----- Running table test 10: Read a QQmlListProperty property into a Go slice -----
----- Running table test 11: Read a QQmlListReference property into a Go slice -----
----- Running table test 12: Read a QVariantList property into a Go slice -----
----- Running table test 13: Set a Go slice property -----
----- Running table test 14: Set a Go slice property with objects -----
----- Running table test 15: Call a method with a JSON object (issue #48) -----
----- Running table test 16: Read a map from a QML property -----
----- Running table test 17: Identical values remain identical when possible -----
[LOG] 36.85478 file.qml:3: Identical: true
----- Running table test 18: Object finding via objectName -----
----- Running table test 19: Register Go type -----
[LOG] 36.85478 file.qml:3: String is <initial>
----- Running table test 20: Register Go type with an explicit name -----
[LOG] 36.85478 file.qml:3: String is <initial>
----- Running table test 21: Write Go type property -----
----- Running table test 22: Write Go type property that has a setter -----
----- Running table test 23: Write Go type property that has a setter and a getter -----
[LOG] 36.85478 file.qml:5: Getter returned <content>
----- Running table test 24: Write an inline object list to a Go type property -----
[LOG] 36.85478 file.qml:6: Length: 2
[LOG] 36.85478 file.qml:7: Name: on
----- Running table test 25: Write an inline object list to a Go type property that has a setter -----
----- Running table test 26: Clear an object list in a Go type property -----
----- Running table test 27: Clear an object list in a Go type property that has a setter -----
----- Running table test 28: Access underlying Go value with Interface -----
----- Running table test 29: Notification signals on custom Go type -----
----- Running table test 30: Singleton type registration -----
[LOG] 36.85478 file.qml:3: String is <initial>
----- Running table test 31: qml.Changed on unknown value is okay -----
----- Running table test 32: qml.Changed triggers a QML slot -----
[LOG] 36.85478 file.qml:5: String is <new>
[LOG] 36.85478 file.qml:6: String at addr is <new at addr>
----- Running table test 33: qml.Changed must not trigger on the wrong field -----
----- Running table test 34: qml.Changed updates bindings -----
----- Running table test 35: Call a Go method without arguments or result -----
[LOG] 36.85478 file.qml:3: Undefined is undefined
----- Running table test 36: Call a Go method with one argument and one result -----
[LOG] 36.85478 file.qml:3: String was <old>
----- Running table test 37: Call a Go method with multiple results -----
[LOG] 36.85478 file.qml:6: mod is 2 and err is undefined
----- Running table test 38: Call a Go method that returns an error -----
[LOG] 36.85478 file.qml:6: err is <division by zero>
----- Running table test 39: Call a Go method that recurses back into the GUI thread -----
[LOG] 36.85478 file.qml:6: Notification arrived
----- Running table test 40: Connect a QML signal to a Go method -----
----- Running table test 41: Call a QML method with no result or parameters from Go -----
[LOG] 36.85478 file.qml:3: f was called
----- Running table test 42: Call a QML method with result and parameters from Go -----
----- Running table test 43: Call a QML method with a custom type -----
[LOG] 36.85478 file.qml:3: String is <content>
----- Running table test 44: Call a QML method that returns a QML object -----
----- Running table test 45: Call a QML method that holds a custom type past the return point -----
[LOG] 36.85478 file.qml:6: String is <content>
qml_test.go:1285:
    t.Done(&testData)
qml_test.go:920:
    c.Check(qml.Stats().ValuesAlive, Equals, stats.ValuesAlive)
... obtained int = 2
... expected int = 1

OOPS: 9 passed, 1 FAILED
--- FAIL: Test (7.80 seconds)
FAIL
exit status 1
FAIL    gopkg.in/qml.v1 7.944s
20:26 ~/code/go/src/gopkg.in/qml.v1 $

Unfortunately I also saw this when updating a testapp to v1:

2014/05/22 20:31:39 qcoreapplication.cpp:1119: QApplication::exec: Must be called from the main thread

The app now freezes instead of crashing though when this happens in case that's of any help.

ablegao commented 10 years ago

Oh, i will try to do small things with it . I have a game server project ,maybe  it can be used to do the test tool. --  Able Gao 高恩博 | 13488828861 | twitter.com/ablegao | weibo.com/ablegao | ablegao.com | weixin:ablegao1

开启 2014年5月23日 at 上午2:23:10, Gustavo Niemeyer (notifications@github.com) 写:

Not all examples were ported yet. If you feel uneasy with the in-development branch, that's totally okay. We can wait until somebody else has the chance to have a look at it.

— Reply to this email directly or view it on GitHub.

niemeyer commented 10 years ago

@quarnster Curious about the "run from main thread" message. Are you putting the qml logic within the function provided to qml.Run? In theory all logic is being run from the main thread in that case, and the initialization is being done before anything else.

If you have a moment to investigate, I'd appreciate some details about it. Thanks for the feedback in either case, though.

quarnster commented 10 years ago

Define "the qml logic" :)

No qml api is touched before the qml.Run, once execution is in the argument provided function several go routines are started which might or might not make the occasional call into qml.

Like before it doesn't occur on every execution (most launches are just fine), so I have no consistent repro case nor a small test app where it occurs. Using this logger:

func (m *mylog) dummy() {
    runtime.Breakpoint()
}
func (m *mylog) QmlOutput(message qml.LogMessage) error {
    log4go.Debug("qml: %s", message.String())
    if strings.Contains(message.String(), "qcoreapplication.cpp:1119") {
        m.dummy()
    }
    return nil
}

And manually setting a breakpoint in mylog.dummy, I get the following backtrace with lldb:

Process 83786 launched: './qml' (x86_64)
Process 83786 stopped
* thread #6: tid = 0x4e6b56, 0x00000000040588e0 qml`main.(*mylog).dummy, stop reason = breakpoint 1.1
    frame #0: 0x00000000040588e0 qml`main.(*mylog).dummy
qml`main.(*mylog).dummy:
-> 0x40588e0:  movq   %gs:0x8a0, %rcx
   0x40588e9:  cmpq   (%rcx), %rsp
   0x40588ec:  ja     0x40588f5                 ; main.(*mylog).dummy + 21
   0x40588ee:  callq  0x4084d80                 ; runtime.morestack8_noctxt
(lldb) bt all
  thread #1: tid = 0x4e6b3a, 0x00007fff8ee18716 libsystem_kernel.dylib`__psynch_cvwait + 10, queue = 'com.apple.main-thread'
    frame #0: 0x00007fff8ee18716 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff957b7c3b libsystem_pthread.dylib`_pthread_cond_wait + 727
    frame #2: 0x0000000005d6dfa1 QtCore`QWaitConditionPrivate::wait(unsigned long) + 49
    frame #3: 0x0000000005d6de5a QtCore`QWaitCondition::wait(QMutex*, unsigned long) + 170
    frame #4: 0x00000000059925d9 QtQml`QQmlThread::QQmlThread() + 217
    frame #5: 0x0000000005926192 QtQml`QQmlTypeLoader::QQmlTypeLoader(QQmlEngine*) + 34
    frame #6: 0x00000000058c705c QtQml`QQmlEnginePrivate::QQmlEnginePrivate(QQmlEngine*) + 268
    frame #7: 0x00000000058c93c7 QtQml`QQmlEngine::QQmlEngine(QObject*) + 55
    frame #8: 0x0000000004006242 qml`newEngine + 34
    frame #9: 0x00000000040058d1 qml`_cgo_affc754e75c8_Cfunc_newEngine + 17

  thread #2: tid = 0x4e6b52, 0x00007fff8ee19662 libsystem_kernel.dylib`kevent64 + 10, queue = 'com.apple.libdispatch-manager'
    frame #0: 0x00007fff8ee19662 libsystem_kernel.dylib`kevent64 + 10
    frame #1: 0x00007fff9940643d libdispatch.dylib`_dispatch_mgr_invoke + 239
    frame #2: 0x00007fff99406152 libdispatch.dylib`_dispatch_mgr_thread + 52

  thread #3: tid = 0x4e6b53, 0x00000000040865dc qml`runtime.usleep + 44
    frame #0: 0x00000000040865dc qml`runtime.usleep + 44

  thread #4: tid = 0x4e6b54, 0x0000000004086703 qml`runtime.mach_semaphore_timedwait + 19
    frame #0: 0x0000000004086703 qml`runtime.mach_semaphore_timedwait + 19
    frame #1: 0x0000000004068ca3 qml`runtime.semasleep + 83
    frame #2: 0x000000000405f233 qml`notetsleep + 195
    frame #3: 0x000000000405f48b qml`runtime.notetsleepg + 155

  thread #5: tid = 0x4e6b55, 0x00000000041fa9b0 qml`syscall.Syscall6 + 48
    frame #0: 0x00000000041fa9b0 qml`syscall.Syscall6 + 48

* thread #6: tid = 0x4e6b56, 0x00000000040588e0 qml`main.(*mylog).dummy, stop reason = breakpoint 1.1
  * frame #0: 0x00000000040588e0 qml`main.(*mylog).dummy

  thread #7: tid = 0x4e6b57, 0x00000000040865dc qml`runtime.usleep + 44
    frame #0: 0x00000000040865dc qml`runtime.usleep + 44
    frame #1: 0x0000000004069001 qml`runtime.osyield + 17
    frame #2: 0x000000000405ee2d qml`runtime.lock + 317

  thread #8: tid = 0x4e6b58, 0x00000000040866eb qml`runtime.mach_semaphore_wait + 11
    frame #0: 0x00000000040866eb qml`runtime.mach_semaphore_wait + 11

  thread #9: tid = 0x4e6b59, 0x0000000004086554 qml`runtime.mmap + 36
    frame #0: 0x0000000004086554 qml`runtime.mmap + 36
    frame #1: 0x00000000040605dc qml`runtime.SysMap + 108
    frame #2: 0x0000000004065a89 qml`runtime.MHeap_MapBits + 201

  thread #10: tid = 0x4e6b5a, 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #0: 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #1: 0x00007fff957b6f08 libsystem_pthread.dylib`_pthread_wqthread + 330

  thread #11: tid = 0x4e6b5b, 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #0: 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #1: 0x00007fff957b6f08 libsystem_pthread.dylib`_pthread_wqthread + 330

  thread #12: tid = 0x4e6b5c, 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #0: 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #1: 0x00007fff957b6f08 libsystem_pthread.dylib`_pthread_wqthread + 330

  thread #13: tid = 0x4e6b5d, 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #0: 0x00007fff8ee18e6a libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #1: 0x00007fff957b6f08 libsystem_pthread.dylib`_pthread_wqthread + 330

  thread #14: tid = 0x4e6b66, 0x0000000005f992c0 QtCore`QEventDispatcherUNIXPrivate::QEventDispatcherUNIXPrivate()
    frame #0: 0x0000000005f992c0 QtCore`QEventDispatcherUNIXPrivate::QEventDispatcherUNIXPrivate()
    frame #1: 0x0000000005f9a475 QtCore`QEventDispatcherUNIX::QEventDispatcherUNIX(QObject*) + 37
    frame #2: 0x0000000005d6c807 QtCore`QThreadPrivate::start(void*) + 231
    frame #3: 0x00007fff957b5899 libsystem_pthread.dylib`_pthread_body + 138
    frame #4: 0x00007fff957b572a libsystem_pthread.dylib`_pthread_start + 137

And gdb says:

(gdb) t a a bt

Thread 13 (Thread 0x2303 of process 83896):
#0  0x00007fff8ee189aa in ?? ()
#1  0x0000000005f98f23 in ?? ()
#2  0x0000000000002b95 in ?? ()
#3  0x0000000000000000 in ?? ()

Thread 12 (Thread 0x2203 of process 83896):
#0  0x00007fff8ee18e6a in ?? ()
#1  0x00007fff957b6f08 in ?? ()
#2  0x0000000002000170 in ?? ()
#3  0x00000000b052f000 in ?? ()
#4  0x0000000000070001 in ?? ()
#5  0x0000000000005503 in ?? ()
#6  0x00000000b052ef78 in ?? ()
#7  0x00007fff957b9fb9 in ?? ()
#8  0x0000000000000000 in ?? ()

Thread 11 (Thread 0x2103 of process 83896):
#0  0x00007fff8ee18e6a in ?? ()
#1  0x00007fff957b6f08 in ?? ()
#2  0x0000000002000170 in ?? ()
#3  0x00000000b04ac000 in ?? ()
#4  0x0000000000070001 in ?? ()
#5  0x0000000000003a07 in ?? ()
#6  0x00000000b04abf78 in ?? ()
#7  0x00007fff957b9fb9 in ?? ()
#8  0x0000000000000000 in ?? ()

Thread 10 (Thread 0x2003 of process 83896):
#0  0x00007fff8ee18e6a in ?? ()
#1  0x00007fff957b6f08 in ?? ()
#2  0x0000000002000170 in ?? ()
#3  0x00000000b0429000 in ?? ()
#4  0x0000000000070001 in ?? ()
#5  0x0000000000002c03 in ?? ()
#6  0x00000000b0428f78 in ?? ()
#7  0x00007fff957b9fb9 in ?? ()
#8  0x0000000000000000 in ?? ()

Thread 9 (Thread 0x1f03 of process 83896):
#0  0x00000000041fa9b0 in syscall.Syscall6 ()
#1  0x00000000041f7ffd in syscall.kevent ()
#2  0x000000000000016b in ?? ()
#3  0x0000000000000008 in ?? ()
#4  0x0000000000000000 in ?? ()

Thread 8 (Thread 0x1e03 of process 83896):
#0  0x00000000040866eb in runtime.mach_semaphore_wait ()
#1  0x0000000004068cf1 in runtime.semasleep ()
#2  0x0000000200002803 in ?? ()
#3  0x000000c208014528 in ?? ()
#4  0x0000000004068cf1 in runtime.semasleep ()
#5  0x000000000405ef27 in runtime.unlock ()
#6  0x0000000004589c20 in runtime.size_to_class8 ()
#7  0x000000000405f158 in runtime.notesleep ()
#8  0xffffffffffffffff in ?? ()
#9  0x0000000000000000 in ?? ()

Thread 7 (Thread 0x1d03 of process 83896):
#0  0x00000000040866eb in runtime.mach_semaphore_wait ()
#1  0x0000000004068cf1 in runtime.semasleep ()
#2  0x0000000000002203 in ?? ()
#3  0x0000000000001b03 in ?? ()
#4  0x000000000405f074 in runtime.notewakeup ()
#5  0x000000000405ef27 in runtime.unlock ()
---Type <return> to continue, or q <return> to quit---
#6  0x0000000004589c20 in runtime.size_to_class8 ()
#7  0x000000000405f158 in runtime.notesleep ()
#8  0xffffffffffffffff in ?? ()
#9  0x0000000000000000 in ?? ()

Thread 6 (Thread 0x1c03 of process 83896):
#0  0x0000000004086703 in runtime.mach_semaphore_timedwait ()
#1  0x0000000004068ca3 in runtime.semasleep ()
#2  0x0000003c00001d03 in ?? ()
#3  0x0000000000000000 in ?? ()

Thread 5 (Thread 0x1b03 of process 83896):
#0  0x00000000040866eb in runtime.mach_semaphore_wait ()
#1  0x0000000004068cf1 in runtime.semasleep ()
#2  0x0000000000001b03 in ?? ()
#3  0x0000000000002803 in ?? ()
#4  0x000000000405f074 in runtime.notewakeup ()
#5  0x000000000405ef27 in runtime.unlock ()
#6  0x0000000004589c20 in runtime.size_to_class8 ()
#7  0x000000000405f158 in runtime.notesleep ()
#8  0xffffffffffffffff in ?? ()
#9  0x0000000000000000 in ?? ()

Thread 4 (Thread 0x1a03 of process 83896):
#0  0x00000000040865dc in runtime.usleep ()
#1  0x0000000000000000 in ?? ()

Thread 3 (Thread 0x1903 of process 83896):
#0  0x00007fff8ee19662 in ?? ()
#1  0x00007fff9940643d in ?? ()
#2  0x0000000000000000 in ?? ()

Thread 2 (Thread 0x180b of process 83896):
#0  0x00000000040588e0 in main.(*mylog).dummy ()
#1  0x0000000004058a9b in main.(*mylog).QmlOutput ()
#2  0x0000000004588da0 in runtime.sysargs ()
#3  0x0000000000000052 in ?? ()
#4  0x00000000043e2d30 in string.* ()
#5  0x0000000000000019 in ?? ()
#6  0x0000000000000001 in ?? ()
#7  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x160b of process 83896):
#0  0x000000000587d3a0 in ?? ()
#1  0x0000000005849278 in ?? ()
#2  0x00007fff5fbff338 in ?? ()
#3  0x0000000006519100 in ?? ()
#4  0x00007fff5fbfefd0 in ?? ()
#5  0x000000000000004a in ?? ()
#6  0x00000000065125b0 in ?? ()
#7  0x000000000b9eb000 in ?? ()
#8  0x0000000006517100 in ?? ()
#9  0x00000000cdd5f031 in ?? ()
#10 0x00007fff5fbff020 in ?? ()
#11 0x00000000058494f0 in ?? ()
#12 0x00007fff5fbff338 in ?? ()
#13 0x00007fff8fca227c in ?? ()
#14 0x0000000006517100 in ?? ()
#15 0x0000000007031600 in ?? ()
#16 0x0000000800000001 in ?? ()
#17 0x0000000006519218 in ?? ()
#18 0x0000000006517100 in ?? ()
#19 0x0000000006519100 in ?? ()
#20 0x00007fff5fbff380 in ?? ()
#21 0x000000000583345c in ?? ()
#22 0x000000015fbff170 in ?? ()
---Type <return> to continue, or q <return> to quit---
#23 0x00007fff5fc3c8f0 in ?? ()
#24 0x00007fff5fc340b0 in ?? ()
#25 0x00007fff5fc3c8f0 in ?? ()
#26 0x00000000063aba00 in ?? ()
#27 0x00000000063aba00 in ?? ()
#28 0x00000000063a8000 in ?? ()
#29 0x00000000063ae200 in ?? ()
#30 0x0000000000000009 in ?? ()
#31 0x00000000063ae200 in ?? ()
#32 0x00007fff5fbff0c0 in ?? ()
#33 0x00007fff8fc9f272 in ?? ()
#34 0x00000009063aba00 in ?? ()
#35 0x00000000063aba00 in ?? ()
#36 0x0000000010800000 in ?? ()
#37 0x00000000063ae200 in ?? ()
#38 0x0000000006515330 in ?? ()
#39 0x0000000000002800 in ?? ()
#40 0x00007fff5fbff1a0 in ?? ()
#41 0x00007fff8fc9f6ca in ?? ()
#42 0x00000001063aba00 in ?? ()
#43 0x0000000000000002 in ?? ()
#44 0x0000000000002800 in ?? ()
#45 0x0000000000000088 in ?? ()
#46 0x0000000005aa7f30 in ?? ()
#47 0x00000000063a8000 in ?? ()
#48 0x0000000000001004 in ?? ()
#49 0x00007fff8fc9f333 in ?? ()
#50 0x00000000063ae200 in ?? ()
#51 0x0000000000000000 in ?? ()
quarnster commented 10 years ago

Not running it in a debugger and letting it crash with GOTRACEBACK=2 gave a more meaningful backtrace:

SIGTRAP: trace trap
PC=0x40831a1

goroutine 16 [running]:
runtime.breakpoint()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/asm_amd64.s:113 +0x1 fp=0xc2080e1e88
runtime.Breakpoint()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:1990 +0x1a fp=0xc2080e1e90
main.(*mylog).dummy(0x4588da0)
    /Users/quarnster/code/go/src/github.com/limetext/lime/frontend/qml/main.go:448 +0x1a fp=0xc2080e1e98
main.(*mylog).QmlOutput(0x4588da0, 0x676d910, 0xc2080c6000, 0x0, 0x0)
    /Users/quarnster/code/go/src/github.com/limetext/lime/frontend/qml/main.go:453 +0x19b fp=0xc2080e1f28
gopkg.in/qml%2ev1.hookLogHandler(0xb03a5ac8)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/log.go:105 +0x139 fp=0xc2080e1fa0
----- stack segment boundary -----
runtime.cgocallbackg1()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/cgocall.c:271 +0xb9 fp=0xc20806be28
runtime.cgocallbackg()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/cgocall.c:243 +0x47 fp=0xc20806be38
runtime.cgocallback_gofunc(0x405e2fd, 0x4004f50, 0xc20806beb0)
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/asm_amd64.s:770 +0x67 fp=0xc20806be48
runtime.asmcgocall(0x4004f50, 0xc20806beb0)
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/asm_amd64.s:676 +0x3a fp=0xc20806be50
runtime.cgocall(0x4004f50, 0xc20806beb0)
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/cgocall.c:143 +0xfd fp=0xc20806be98
gopkg.in/qml%2ev1._Cfunc_applicationExec(0x433b1a0)
    gopkg.in/qml.v1/_obj/_cgo_defun.c:71 +0x31 fp=0xc20806beb0
gopkg.in/qml%2ev1.Run(0x0, 0xc208001f60, 0x0, 0x0)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/bridge.go:66 +0x1ac fp=0xc20806bf10
main.main()
    /Users/quarnster/code/go/src/github.com/limetext/lime/frontend/qml/main.go:700 +0x10e fp=0xc20806bf50
runtime.main()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:247 +0x11a fp=0xc20806bfa8
runtime.goexit()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:1430 fp=0xc20806bfb0
created by _rt0_go
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/asm_amd64.s:97 +0x120

goroutine 19 [finalizer wait]:
runtime.park(0x406d650, 0x45881a8, 0x45797c9)
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:1354 +0x89
runtime.parkunlock(0x45881a8, 0x45797c9)
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:1370 +0x3b
runfinq()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/mgc0.c:2624 +0xcf
runtime.goexit()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:1430

goroutine 17 [syscall]:
runtime.goexit()
    /Users/quarnster/code/3rdparty/go/src/pkg/runtime/proc.c:1430

goroutine 21 [chan receive]:
github.com/quarnster/util/text.(*SerializedBuffer).worker(0xc208040248)
    /Users/quarnster/code/go/src/github.com/quarnster/util/text/serialized_buffer.go:39 +0x5e
created by github.com/quarnster/util/text.(*SerializedBuffer).init
    /Users/quarnster/code/go/src/github.com/quarnster/util/text/serialized_buffer.go:26 +0x88

goroutine 22 [runnable]:
syscall.Syscall6(0x16b, 0x4, 0x0, 0x0, 0x67b1e58, 0xa, 0x67b1d30, 0x0, 0x0, 0x0, ...)
    /Users/quarnster/code/3rdparty/go/src/pkg/syscall/asm_darwin_amd64.s:41 +0x5
syscall.kevent(0x4, 0x0, 0x0, 0x67b1e58, 0xa, 0x67b1d30, 0x429a8a0, 0x0, 0x0)
    /Users/quarnster/code/3rdparty/go/src/pkg/syscall/zsyscall_darwin_amd64.go:200 +0x9d
syscall.Kevent(0x4, 0x0, 0x0, 0x0, 0x67b1e58, 0xa, 0xa, 0x67b1d30, 0x0, 0x0, ...)
    /Users/quarnster/code/3rdparty/go/src/pkg/syscall/syscall_bsd.go:447 +0xbb
github.com/howeyc/fsnotify.(*Watcher).readEvents(0xc208028340)
    /Users/quarnster/code/go/src/github.com/howeyc/fsnotify/fsnotify_bsd.go:333 +0x35d
created by github.com/howeyc/fsnotify.NewWatcher
    /Users/quarnster/code/go/src/github.com/howeyc/fsnotify/fsnotify_bsd.go:107 +0x2fc

goroutine 23 [chan receive]:
github.com/howeyc/fsnotify.(*Watcher).purgeEvents(0xc208028340)
    /Users/quarnster/code/go/src/github.com/howeyc/fsnotify/fsnotify.go:21 +0x54
created by github.com/howeyc/fsnotify.NewWatcher
    /Users/quarnster/code/go/src/github.com/howeyc/fsnotify/fsnotify_bsd.go:108 +0x314

goroutine 24 [runnable]:
fmt.Sprintf(0x439f830, 0xa, 0x67aff68, 0x3, 0x3, 0x0, 0x0)
    /Users/quarnster/code/3rdparty/go/src/pkg/fmt/print.go:204 +0x9d
github.com/limetext/lime/backend.(*myLogWriter).handle(0xc20803e060)
    /Users/quarnster/code/go/src/github.com/limetext/lime/backend/editor.go:98 +0x1d7
created by github.com/limetext/lime/backend.newMyLogWriter
    /Users/quarnster/code/go/src/github.com/limetext/lime/backend/editor.go:91 +0x69

goroutine 25 [chan receive]:
github.com/limetext/lime/backend.(*Editor).inputthread(0xc2080bc000)
    /Users/quarnster/code/go/src/github.com/limetext/lime/backend/editor.go:325 +0xb2
created by github.com/limetext/lime/backend.GetEditor
    /Users/quarnster/code/go/src/github.com/limetext/lime/backend/editor.go:146 +0x3e6

goroutine 26 [select]:
github.com/limetext/lime/backend.(*Editor).observeFiles(0xc2080bc000)
    /Users/quarnster/code/go/src/github.com/limetext/lime/backend/editor.go:366 +0x25b
created by github.com/limetext/lime/backend.GetEditor
    /Users/quarnster/code/go/src/github.com/limetext/lime/backend/editor.go:147 +0x401

goroutine 27 [runnable]:
reflect.TypeOf(0x42a70a0, 0xc2080f4060, 0xc2080f4050, 0x76)
    /Users/quarnster/code/3rdparty/go/src/pkg/reflect/type.go:1005
fmt.(*pp).doPrint(0xc2080f6000, 0x67acf18, 0x7, 0x7, 0x4070000)
    /Users/quarnster/code/3rdparty/go/src/pkg/fmt/print.go:1189 +0xc0
fmt.Fprint(0x67673a8, 0xc20803e050, 0x67acf18, 0x7, 0x7, 0xc2080ee000, 0x0, 0x0)
    /Users/quarnster/code/3rdparty/go/src/pkg/fmt/print.go:222 +0x87
code.google.com/p/log4go.ConsoleLogWriter.run(0xc208024420, 0x67673a8, 0xc20803e050)
    /Users/quarnster/code/go/src/code.google.com/p/log4go/termlog.go:31 +0x3f7
created by code.google.com/p/log4go.NewConsoleLogWriter
    /Users/quarnster/code/go/src/code.google.com/p/log4go/termlog.go:19 +0x68

goroutine 28 [runnable]:
gopkg.in/qml%2ev1._Cfunc_CString(0xc20813a080, 0x7a, 0x7a)
    gopkg.in/qml.v1/_obj/_cgo_defun.c:52 +0x2a
gopkg.in/qml%2ev1.typeInfo(0x4367b00, 0xc2080239e0, 0xc2080c99c0)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/datatype.go:355 +0x7e4
gopkg.in/qml%2ev1.wrapGoValue(0xc208023a70, 0x4367b00, 0xc2080239e0, 0x1, 0x0)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/bridge.go:254 +0x477
gopkg.in/qml%2ev1.packDataValue(0x4367b00, 0xc2080239e0, 0xc208124030, 0xc208023a70, 0x1)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/datatype.go:116 +0x224
gopkg.in/qml%2ev1.func·014()
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/qml.go:268 +0x84
gopkg.in/qml%2ev1.RunMain(0xc208128000)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/bridge.go:78 +0xe1
gopkg.in/qml%2ev1.(*Context).SetVar(0xc20810a030, 0x43ad1b0, 0x8, 0x4367b00, 0xc2080239e0)
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/qml.go:274 +0x10b
main.func·002(0x0, 0x0)
    /Users/quarnster/code/go/src/github.com/limetext/lime/frontend/qml/main.go:485 +0x1dd
main.(*qmlfrontend).loop(0xc2080239e0, 0x0, 0x0)
    /Users/quarnster/code/go/src/github.com/limetext/lime/frontend/qml/main.go:493 +0x1a1
main.*qmlfrontend.(main.loop)·fm(0x0, 0x0)
    /Users/quarnster/code/go/src/github.com/limetext/lime/frontend/qml/main.go:700 +0x4a
gopkg.in/qml%2ev1.func·002()
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/bridge.go:63 +0x46
created by gopkg.in/qml%2ev1.Run
    /Users/quarnster/code/go/src/gopkg.in/qml.v1/bridge.go:65 +0x1a5

rax     0x1
rbx     0x4588da0
rcx     0xc208002120
rdx     0x393131313a707063
rdi     0x1fcfde4d
rsi     0x52
rbp     0x43e2730
rsp     0xc2080e1e80
r8      0x0
r9      0x0
r10     0x19
r11     0x19
r12     0x0
r13     0x0
r14     0x45f
r15     0x10
rip     0x40831a1
rflags  0x206
cs      0x2b
fs      0xffff0000
gs      0xfffe0000
quarnster commented 10 years ago

TL;DR: add runtime.LockOSThread() to the entry of qml.Run.

I think I've tracked this down. qml calls runtime.LockOSThread() in it's niladic init function, but somewhere between that and in the entry of qml.RunMain someone calls runtime.UnlockOsThread() or some other condition for go routine exit is satisfied so that the OS thread becomes unbound from the main go routine.

This theory is quite easy to try out with some code similar to this:

func main() {
    var wg sync.WaitGroup
    wg.Add(1)
    go func() {
        defer func() {
            if e := recover(); e != nil {
                log.Println("received a panic this time:", e)
            }
            wg.Done()
        }()
        log.Println("ran fine:", qml.Run(nil, mymain))
    }()
    wg.Wait()
}

Now it should always see a panic if the goroutine is indeed bound to the current os thread, but my program is able to successfully launch some times which to me indicates that the main thread has become unbound.

In the following code in qml's Run method then:

    go func() {
        RunMain(func() {}) // Block until the event loop is running.
        done <- f()
        C.applicationExit()
    }()
    C.applicationExec()

as indicated in the stack trace above my f function (gorutine 28) is already running when applicationExec() (goroutine 16) is called!

RunMain when called in the main or gui thread just immediately executes the provided function, and if the main thread has become unbound it's not unreasonable that RunMain and f continue to run in the main native OS thread while applicationExec is executed in another.

The solution is quite simply to just call runtime.LockOSThread again at the entry of qml.Run, guaranteeing that the QCoreApplication is created and its exec is called from within the same thread.

niemeyer commented 10 years ago

as indicated in the stack trace above my f function (gorutine 28) is already running when applicationExec() (goroutine 16) is called!

I'm not sure I get your point. The stack trace shows both executing concurrently. How are you observing the order in which they have run?

RunMain when called in the main or gui thread just immediately executes the provided function, and if the main thread has become unbound it's not unreasonable that RunMain and f continue to run in the main native OS thread while applicationExec is executed in another.

It does sound unreasonable to have RunMain executed in the main thread if it is in a different goroutine than the one that called LockOSThread on the main one, unless there's either a relevant bug in the runtime, or something else is calling UnlockOSThread in a very improper way.

Does that make sense, or can you shed some further light on it?

Also, have you had a chance to experiment further on it? Sorry, I'm in a sprint and a bit slow to respond this week.

quarnster commented 10 years ago

as indicated in the stack trace above my f function (gorutine 28) is already running when applicationExec() (goroutine 16) is called!

I'm not sure I get your point. The stack trace shows both executing concurrently. How are you observing the order in which they have run?

My point is that they shouldn't run concurrently. The point where the "must be called from the main thread" message is printed, it also returns from QCoreApplication::exec, meaning that the code that is supposed to launch the event loop is never reached.

Remember from my previous comment that I'm triggering a breakpoint when spotting the "Must run" message.

So here are the facts:

In other words, RunMain which should still be blocking my function from being called didn't. As the event loop was never started, the only possible conclusion is that RunMain is running in the main thread.

It does sound unreasonable to have RunMain executed in the main thread if it is in a different goroutine than the one that called LockOSThread on the main one, unless there's either a relevant bug in the runtime, or something else is calling UnlockOSThread in a very improper way.

Is init and main considered to be part of the same goroutine?

Nonetheless, AFAIK there's no api for getting whether a goroutine is locked to the current thread or not and it's not unreasonable to think that some library only needs temporary locking meaning it calls both LockOSThread and then UnlockOSThread when done. These calls aren't "reference" counted so two locks and one unlock is no different from a single lock and an unlock.

My TL;DR stays the same: add runtime.LockOSThread() to the entry of qml.Run.

quarnster commented 10 years ago

Also, doesn't this mean that the runtime itself calls UnlockOSThread before main.main is entered?

quarnster commented 10 years ago

Or, you know, two lines above the call to main.main, where unlockOSThread is explicitly called :)

niemeyer commented 10 years ago

My point is that they shouldn't run concurrently.

They must run concurrently. applicationExec runs the main GUI loop. Without it running there's no way for the function f() to run any qml-related logic.

The point where the "must be called from the main thread" message is printed, it also returns from QCoreApplication::exec, meaning that the code that is supposed to launch the event loop is never reached.

Sure, that's the problem we're fixing.

In other words, RunMain which should still be blocking my function from being called didn't.

Not necessarily. It looks like it did block before preparing the main loop to run, but the event loop can unblock it, even if it does return.

Is init and main considered to be part of the same goroutine?

From runtime·main:

    // Lock the main goroutine onto this, the main OS thread,
    // during initialization.  Most programs won't care, but a few
    // do require certain calls to be made by the main thread.
    // Those can arrange for main.main to run in the main thread
    // by calling runtime.LockOSThread during initialization
    // to preserve the lock.
    runtime·lockOSThread();

My TL;DR stays the same: add runtime.LockOSThread() to the entry of qml.Run.

That does not help. The point is locking down the thread so that qml.Run is guaranteed to be run in the main thread. By the time it runs, it's too late.

Or, you know, two lines above the call to main.main, where unlockOSThread is explicitly called :)

See the comment above.

quarnster commented 10 years ago

They must run concurrently. applicationExec runs the main GUI loop. Without it running there's no way for the function f() to run any qml-related logic.

My function should run once the main gui loop exists and until then it shouldn't.

Not necessarily. It looks like it did block before preparing the main loop to run, but the event loop can unblock it, even if it does return.

There is no event loop. It hasn't been created yet. Again the "Must run in main thread" message at line 890, followed by a return from QCoreApplication::Exec at line 891 occurs before the event loop is created at line 899 and consequently then also before it is then executed at line 902.

That does not help. The point is locking down the thread so that qml.Run is guaranteed to be run in the main thread. By the time it runs, it's too late.

You can't guarantee that qml.Run is run in the main thread as there's no way to guarantee that someone doesn't unlock thread. You can however guarantee that qml.Run is called in the same thread that runs applicationExec by locking the thread there. If this was not the main OS thread the function panics, and if it was the main OS thread it'll work as expected.

niemeyer commented 10 years ago

My function should run once the main gui loop exists and until then it shouldn't.

This loops back to the beginning of the conversation.

There is no event loop. It hasn't been created yet. Again the "Must run in main thread" message

This message comes from Qt, and generally means that the code has really run qml.Run out of the initial goroutine. If you can demonstrate with some correct code that this happens in other circumstances, that would certainly be very interesting.

Note that this is the message in the comment that created this issue:

2014-05-23 01:41:40.056 customtype[44170:1b03] +[NSUndoManager(NSInternal) _endTopLevelGroupings] is only safe to invoke on the main thread.

This is a message coming from Mac OS itself, and it's my understanding that the event loop is in fact running by then.

You can't guarantee that qml.Run is run in the main thread as there's no way to guarantee that someone doesn't unlock thread.

It's not my intention to guarantee that. If they call UnlockOSThread without calling LockOSThread, it's obviously a broken application and the error message is very correct and informative.

quarnster commented 10 years ago

Regarding main loop qml.RunMain(func() {log.Println("hello world")}) without any other calls prints out so looks like you are correct.

It's not my intention to guarantee that. If they call UnlockOSThread without calling LockOSThread, it's obviously a broken application and the error message is very correct and informative.

Do you consider the sequence of calling Lock once and then Unlock once unreasonable and obviously broken usage?

The consequence of not having an extra lock in qml.Run is that the whole app will randomly freeze at launch when it just so happens that applicationExec is run in another OS thread than the main one.

The consequence of having the extra lock in qml.Run is that the function either panics with a clear error message or that everything works as expected.

niemeyer commented 10 years ago

Do you consider the sequence of calling Lock once and then Unlock once unreasonable and obviously broken usage?

No, I see what you mean. Given the comment in runtime, I assumed it'd be a reentrant lock, but it's not. So yes, calling it again inside Run is a good idea, although it still does not guarantee that Run won't be moved out of the main thread in between the unlock and the re-lock, so we'll have to advise people to not call UnlockOSThread, inside the initial goroutine.

That said, I'd like to go back into the issue topic. With the new knowledge, are you able to test it properly on Mac OS? Are there any remaining issues?

quarnster commented 10 years ago

So yes, calling it again inside Run is a good idea, although it still does not guarantee that Run won't be moved out of the main thread in between the unlock and the re-lock, so we'll have to advise people to not call UnlockOSThread, inside the initial goroutine.

Agreed, however if the lock is the first call in Run, it'll be locked when the call to cdata.Ref is made so we can guarantee that this check is valid. It's not possible to unlock this OS thread again until Run exits, correct?

go test gopkg.in/qml.v1 still fails as described in my previous comment, but other than that I have not seen any issues with v1 in "real" apps with the added thread locking.

niemeyer commented 10 years ago

Agreed, however if the lock is the first call in Run, it'll be locked when the call to cdata.Ref is made so we can guarantee that this check is valid. It's not possible to unlock this OS thread again until Run exits, correct?

That's right.

go test gopkg.in/qml.v1 still fails as described in my previous comment, but other than that I have not seen any issues with v1 in "real" apps with the added thread locking.

That sounds promising. Although I cannot tell what's that error, it feels like something simple. Will need someone to debug it, or at least someone I can pair with to solve it. I'll add the extra lock.

quarnster commented 10 years ago

FWIW the output of:

            log.Println(qml.Stats().ValuesAlive, stats.ValuesAlive)
            log.Println(qml.Stats().ValuesAlive, stats.ValuesAlive)

is almost always

2014/05/30 16:14:23 2 1
2014/05/30 16:14:23 1 1

but sometimes

2014/05/30 16:12:08 1 1
2014/05/30 16:12:08 1 1

So perhaps calling gc() only schedules the garbage collector rather than waiting for it to finish? The destruction signal might be of use (or just time.Sleep ;))

niemeyer commented 10 years ago

Quite possibly. Should be trivial to try it out by repeating the call a few times.

niemeyer commented 10 years ago

While verifying the current values within the loop, that is.

niemeyer commented 9 years ago

This was fixed on qml.v1:

http://blog.labix.org/2014/08/13/announcing-qml-v1-for-go