Автор: Любопытная история приключилась со мной намедни. Моя основная C# IDE на никсовых системах — Visual Studio Code — внезапно приказала долго жить. Не целиком, а самая полезная её часть — дебаггер. Стоило мне поставить брейкпоинт где-нибудь в коде и запустить проект, как редактор останавливал праздник интеллекта с ошибкой «Debug adapter process has terminated unexpectedly»:
A вот раньше всё работало просто прекрасно. Так как незадолго до проблемы я устанавливал на Убунту сразу несколько новых связанных с дебаггингом утилит (lldb, perf и lttng), то естественно подумал, что проблема пришла от них. Но ни их удаление, ни переустановка VS Code целиком не изменили ровным счётом ничего.
В довесок к этому единственная внятная альтернатива VS Code для работы с C# на Linux — JetBrains Rider — тоже косячит. Какие-то проекты она может запустить и дебаггить, какие-то — нет. Те, что мне нужны, например, она даже запустить не может. В общем, не оставалось ничего другого кроме как начать разбираться, кто убил VS Code.
Ищем файлы дампов
Ни один процесс на моей Убунте не может умереть насильственной смертью и не оставить после себя дамп файл. Эту фичу я включил достаточно давно для другой задачи, и вот теперь она снова оказалась полезной. Ведь если сообщение об ошибке выглядит как «Debug adapter process has terminated unexpectedly», то, значит, был процесс, была насильственная эвтаназия, и, следовательно, должен быть дамп. И он нашёлся! Прямо в папке VS Code, в плагине, отвечающим за C#:
|
1 2 3 4 5 |
ls ~/.vscode/extensions/ms-vscode.csharp-1.14.0-beta2/.debugger #.. core_vsdbg-ui.1516818450.11328 core_vsdbg-ui.1516819369.17965 #.. |
Судя по имени, падал vsdbg-ui. Он лежит в этой же папке, и теперь можно натравить на него lldb и посмотреть, от чего же тот слёг.
Смотрим предсмертный стек
Итак, берём дебаггер и смотрим в дамп:
|
1 2 3 |
lldb-3.6 vsdbg-ui -c core_vsdbg-ui.1516818450.11328 #... (lldb) |
Обычно первой командой в таких случаях я запускаю backtrace — показать стек текущего потока. Часто наводит на умные мысли:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
(lldb) bt #* thread #1: tid = 0, 0x00007fa6142a8428 libc.so.6`gsignal + 56, name = 'vsdbg-ui', stop reason = signal SIGABRT # * frame #0: 0x00007fa6142a8428 libc.so.6`gsignal + 56 # frame #1: 0x00007fa6142aa02a libc.so.6`abort + 362 # frame #2: 0x00007fa612fdb6cc libcoreclr.so`PROCAbort + 124 # frame #3: 0x00007fa612fda5bb libcoreclr.so`PROCEndProcess(void*, unsigned int, int) + 235 # frame #4: 0x00007fa612d43748 libcoreclr.so`UnwindManagedExceptionPass1(PAL_SEHException&, _CONTEXT*) + 840 # frame #5: 0x00007fa612d437f9 libcoreclr.so`DispatchManagedException(PAL_SEHException&, bool) + 73 # frame #6: 0x00007fa612cb3f2a libcoreclr.so`IL_Throw(Object*) + 794 # frame #7: 0x00007fa5cadc1291 # frame #8: 0x00007fa5cb2c61b2 # frame #9: 0x00007fa612bf2d18 libcoreclr.so`MethodTable::CallFinalizer(Object*) + 600 # frame #10: 0x00007fa612c94c0e libcoreclr.so`FinalizerThread::DoOneFinalization(Object*, Thread*, int, bool*) + 334 # frame #11: 0x00007fa612c94a1a libcoreclr.so`FinalizerThread::FinalizeAllObjects(Object*, int) + 266 # frame #12: 0x00007fa612c9507e libcoreclr.so`FinalizerThread::FinalizerThreadWorker(void*) + 446 # frame #13: 0x00007fa612c30bd2 libcoreclr.so`ManagedThreadBase_DispatchOuter(ManagedThreadCallState*) + 402 # frame #14: 0x00007fa612c3142e libcoreclr.so`ManagedThreadBase::FinalizerBase(void (*)(void*)) + 94 # frame #15: 0x00007fa612c952fc libcoreclr.so`FinalizerThread::FinalizerThreadStart(void*) + 204 # frame #16: 0x00007fa612fdd342 libcoreclr.so`CorUnix::CPalThread::ThreadEntry(void*) + 306 # frame #17: 0x00007fa614b636ba libpthread.so.0`start_thread + 202 # frame #18: 0x00007fa61437a41d libc.so.6`clone + 109 |
Круууто! То есть процесс скончался, печаль-печаль, но судя по libcoreclr.so это был .NET Core процесс и у меня с этим больше шансов разобраться, чем с каким-нибудь C++. Более того, в стеке нашлись слова FinalizerThread и DispatchManagedException, что означает, в очереди деструкторов кто-то бросил ошибку и тем самым завершил процесс. Теперь только надо выяснить, где и что это была за ошибка.
Так как это дамп .NET Core процесса, стоит сначала включить SOS плагин и работать уже с нормальными managed потоками и объектами.
Переходим к управляемому коду
Самый простой способ раздобыть SOS плагин — отдолжить его у .NET Core SDK. У меня как раз есть такой. А с плагином можно получить команду sos PrintException и узнать, что же там за ошибка была.
|
1 2 3 4 5 6 |
(lldb) plugin load /usr/share/dotnet/shared/Microsoft.NETCore.App/2.0.4/libsosplugin.so (lldb) sos PrintException #dlopen(/home/pavelklimenkov/.vscode/extensions/ms-vscode.csharp-1.14.0-beta2/.debugger/libsos.so) failed /home/pavelklimenkov/.vscode/extensions/ms-vscode.csharp-1.14.0-beta2/.debugger/libsos.so: cannot open shared object file: No such file or directory |
Так, оно жалуется на отсутствующий libsos.so. Я определённо знаю, что в .NET Core SDK есть и такой, так что можно тупо скопировать его оттуда в текущую папку и попытаться снова:
|
1 2 3 4 |
cp /usr/share/dotnet/shared/Microsoft.NETCore.App/2.0.4/libsos.so . #... (lldb) sos PrintException The current thread is unmanaged |
«Текущий поток не является управляемым». Не дотнэтовский, то есть. Ну что же, с этим я могу справиться, но для начала интересно, о скольки потоках вообще идёт речь?
Разбираемся с потоками
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
(lldb) sos Threads #ThreadCount: 9 #UnstartedThread: 0 #BackgroundThread: 9 #PendingThread: 0 #DeadThread: 0 #Hosted Runtime: no # Lock # ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception #XXXX 1 2c42 0000000001A70FE0 21220 Preemptive 00007FA5E4231AD0:00007FA5E4232388 0000000001A68F20 0 Ukn (Finalizer) System.NotSupportedException 00007fa5e42303a0 #XXXX 2 2c40 0000000001A88590 2020220 Preemptive 0000000000000000:0000000000000000 0000000001A68F20 0 Ukn #XXXX 3 2c45 0000000001A47F30 1021220 Preemptive 0000000000000000:0000000000000000 0000000001A68F20 0 Ukn (Threadpool Worker) #XXXX 4 2c47 00007FA5DC004BC0 1021220 Preemptive 0000000000000000:0000000000000000 0000000001A68F20 0 Ukn (Threadpool Worker) #XXXX 6 2c49 00007FA5D8004BC0 1021220 Preemptive 0000000000000000:0000000000000000 0000000001A68F20 0 Ukn (Threadpool Worker) #XXXX 5 2c4c 00007FA5CC005600 2020220 Preemptive 0000000000000000:0000000000000000 0000000001A68F20 0 Ukn #XXXX 7 2c4f 00007FA5C0005DE0 20220 Preemptive 0000000000000000:0000000000000000 0000000001A68F20 0 Ukn #XXXX 8 2c57 00007FA5B0009A50 20220 Preemptive 00007FA5E422F948:00007FA5E4230388 0000000001A68F20 0 Ukn #XXXX 9 2c66 00007FA5B8002520 20220 Preemptive 00007FA5E4228650:00007FA5E422A388 0000000001A68F20 0 Ukn |
И ещё раз «Круууто!». Напротив самого первого потока (OSID — 2c42) стоит отметка, что он бросил System.NotSupportedException ошибку. И даже слово Finalizer сбоку — деструктор, то есть. Определённо наш клиент. И там же адрес ошибки — 00007fa5e42303a0, так что можно заглянуть внутрь:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 |
(lldb) dumpobj 00007fa5e42303a0 #Name: System.NotSupportedException #MethodTable: 00007fa603e213b0 #EEClass: 00007fa60363bfb0 #Size: 152(0x98) bytes #File: /home/pavelklimenkov/.vscode/extensions/ms-vscode.csharp-1.14.0-beta2/.debugger/System.Private.CoreLib.dll #Fields: # MT Field Offset Type VT Attr Value Name #00007fa603e1c460 40001cd 8 System.String 0 instance 00007fa5e42305d0 _className #00007fa603e1f8e8 40001ce 10 ...ection.MethodBase 0 instance 0000000000000000 _exceptionMethod #00007fa603e1c460 40001cf 18 System.String 0 instance 0000000000000000 _exceptionMethodString #00007fa603e1c460 40001d0 20 System.String 0 instance 00007fa5e4202f30 _message #00007fa603db95c8 40001d1 28 ...tions.IDictionary 0 instance 0000000000000000 _data #00007fa603e1bff0 40001d2 30 System.Exception 0 instance 0000000000000000 _innerException #00007fa603e1c460 40001d3 38 System.String 0 instance 0000000000000000 _helpURL #00007fa603e1c890 40001d4 40 System.Object 0 instance 00007fa5e42304f8 _stackTrace #00007fa603e1c890 40001d5 48 System.Object 0 instance 0000000000000000 _watsonBuckets #00007fa603e1c460 40001d6 50 System.String 0 instance 0000000000000000 _stackTraceString #00007fa603e1c460 40001d7 58 System.String 0 instance 0000000000000000 _remoteStackTraceString #00007fa603e3c020 40001d8 80 System.Int32 1 instance 0 _remoteStackIndex #00007fa603e1c890 40001d9 60 System.Object 0 instance 0000000000000000 _dynamicMethods #00007fa603e3c020 40001da 84 System.Int32 1 instance -2146233067 _HResult #00007fa603e1c460 40001db 68 System.String 0 instance 0000000000000000 _source #00007fa603e3c2d0 40001dc 70 System.IntPtr 1 instance 0000000000000000 _xptrs #00007fa603e3c020 40001dd 88 System.Int32 1 instance -532462766 _xcode #00007fa603e468e8 40001de 78 System.UIntPtr 1 instance 0000000000000000 _ipForWatsonBuckets #00007fa603e1c890 40001cc 40 System.Object 0 shared static s_EDILock |
Свойство _message тоже не пустое и можно узнать текст ошибки:
|
1 2 3 4 5 6 7 8 9 10 11 12 |
(lldb) dumpobj 00007fa5e4202f30 #Name: System.String #MethodTable: 00007fa603e1c460 #EEClass: 00007fa60363aeb8 #Size: 48(0x30) bytes #File: /home/pavelklimenkov/.vscode/extensions/ms-vscode.csharp-1.14.0-beta2/.debugger/System.Private.CoreLib.dll #String: GetObjectID #Fields: # MT Field Offset Type VT Attr Value Name #00007fa603e3c020 40001c9 8 System.Int32 1 instance 11 m_stringLength #00007fa603e20420 40001ca c System.Char 1 instance 47 m_firstChar #00007fa603e1c460 40001cb 38 System.String 0 shared static Empty |
Зашибись. Какой-то объект не поддерживает метод «GetObjectID». Интересно, какой. Нужно снова посмотреть в поток.
Находим стек ошибки
В прошлый раз PrintException не сработал, потому что текущий поток — не дотнэтовский поток. Но можно привязать проблемный дотнэтовский поток к текущему, нативному, и SOS, возможно, успокоится. Какой там текущий нативный поток?
|
1 2 3 4 5 6 7 |
(lldb) thread list #Process 0 stopped #* thread #1: tid = 0, 0x00007fa6142a8428 libc.so.6`gsignal + 56, name = 'vsdbg-ui', stop reason = signal SIGABRT # thread #2: tid = 1, 0x00007fa614b69360 libpthread.so.0`__pthread_cond_wait + 192, stop reason = signal SIGABRT # thread #3: tid = 2, 0x00007fa61436e74d libc.so.6`__poll + 45, stop reason = signal SIGABRT # thread #4: tid = 3, 0x00007fa614b6cc7d libpthread.so.0, stop reason = signal SIGABRT #.... |
Тоже первый. В общем, надо указать, что CLR поток #1 (OSID — 2c42) и нативный #1 — одно и то же лицо.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
(lldb) setsostid 2c42 1 #Mapped sos OS tid 0x2c42 to lldb thread index 1 (lldb) sos PrintException #Exception object: 00007fa5e42303a0 #Exception type: System.NotSupportedException #Message: GetObjectID #InnerException: <none> #StackTrace (generated): # SP IP Function # 00007FA6124CC9E0 00007FA5CADC1291 System.Private.CoreLib.InteropServices.ni.dll!System.Runtime.InteropServices.InteropExtensions.GetObjectID(System.Object)+0x31 # 00007FA6124CC9F0 00007FA5CB2C6B5F System.Private.Interop.ni.dll!System.__ComObject.Cleanup(Boolean)+0xaf # 00007FA6124CCAB0 00007FA5CB2C61B2 System.Private.Interop.ni.dll!System.RCWFinalizer.Finalize()+0x12 # #StackTraceString: <none> #HResult: 80131515 |
Прекрасный стек, просто прекрасный. Теперь нужно лезть в гугл и искать, о чём этот код вообще. .NET Core же open source теперь.
Работаем с сырцами, и убийца это…
Было достаточно просто найти код InteropExtensions.cs, в котором полагалось быть GetObjectID методу. Там такой есть, и он реально бросает ошибку.
|
1 2 3 4 |
public unsafe static IntPtr GetObjectID(object obj) { throw new NotSupportedException("GetObjectID"); } |
Смотрим, кто его вызывает, и сырцы для __ComObject.Cleanup оказались более полезными, потому что все места, в которых вызывается GetObjectID, выглядят вот так:
|
1 2 |
if (InteropEventProvider.IsEnabled()) InteropEventProvider.Log.TaskRCWFinalization((long)InteropExtensions.GetObjectID(this), this.m_refCount); |
То есть это какой-то встроенный логгинг/трэйсинг. Идём немного в сторону от стека и смотрим, когда InteropEventProvider.IsEnabled может стать true. Великого откровения там тоже нет, но есть интересная идея.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
public static readonly InteropEventProvider Log = new InteropEventProvider(); #if ENABLE_WINRT internal new static bool IsEnabled() { // The InteropEventProvider class constructor should create an instance of InteropEventProvider and assign // it to the Log field so Log should never be null here. However the EventSource performs some P/Invoke // interop and creating a System.Type object which happens while running the EventSource ctor can perform // WinRT interop so it is possible that we end up calling IsEnabled before the InteropEventProvider class // constructor has completed so we must check that Log is not null. return Log != null && ((EventSource)Log).IsEnabled(); } #else |
Там внутри есть EventSource, и я о нём слышал. Одна из вещей, которые делал параллельно с установкой всех этих lldb/lttng и прочих, была установка переменной среды: COMPlus_EnableEventLog. Она включает трассировку в .NET рантайме, мне это было нужно для одной задачи (и блог поста). Рантайм он и есть рантайм, и на vsdbg-ui этот флаг бы тоже распространился. Что если дело в нём? Что если vsdbg-ui, поставляемый с VS Code C# расширением, не поддерживает трассировку по крайней мере на моей машине?
Через минуту я убираю переменную, рестартую сессию, и VS Code снова работает как часы.
Мораль
Есть в мире истории, которые завершаются хэппи эндом, но не совсем удовлетворительным, потому что осталась уйма вопросов. Эта одна из таких. Например, судя по коду, EventSource будет работать только под WinRT билдами. Но ведь у меня Убунта, какой к чертям WinRT?! Потом, было на самом деле две реализации InteropExtensions класса в CoreRT репозитории, и дебаггер почему-то выбрал «неправильную». Как же так? И вообще, почему я не могу повторить эту же ошибку на чистой Убунте с каким-нибудь «Hello World» приложением?
Но с другой стороны, я получил свой дебаггер назад. Если вы думали, что дебаггить JavaScript через alert — верх идиотизма, попробуйте тот же принцип, но с Console.WriteLine и C#.
