Логи Xcode — читаем самостоятельно?
В этой публикации попробуем понять, как и где Xcode хранит свои логи, что такое SLF0 и как все это читать, а может быть даже понять, и лучше без IDE, так интереснее.
Без лишних предисловий.
Чтобы посмотреть логи сборки проекта или скажем тестов, в обычной, повседневной разработке, мы идем и смотрим последнюю вкладку тулбара Xcode.
Организация лога в целом читаемая, даже есть возможность все это экспортировать в txt формат.
Но, все это нам мало подходит для автоматизации сбора метрик, скажем для аккумулирования динамики времени сборки модулей при прогоне job'ы на CI.
Простого пути экспортировать данный лог, в полном объеме для последующей интерпретации конкретных событий нет.
Итак, все логи Xcode собирает и хранит в DerivedData/{ProjectName}/Logs.
Что такое DerivedData
По умолчанию находится по следующему пути:
open ~/Library/Developer/Xcode/DerivedData
Данный путь можно поменять в настройках Xcode:
Собственно, DerivedData хранит всю промежуточную информацию (включая логи), а также артефакты, требуемые для оптимизации последующей сборки.
Внутри папки Logs можно встретить множество логов различных стадий, с которыми мы сталкиваемся во время разработки:
Здесь мы можем найти следующие виды файлов:
*.xcactivitylog
- собственно журнал, который нас будет интересовать далее;*.xcresult
- bundle, который хранит сводную информацию. Можно открыть в Xcode и посмотреть журналы в том виде, как если бы мы просто открыли последнюю вкладку тулбара;LogStoreManifest.plist
- содержит сводную информацию в читаемом виде о всех xcactivitylog файлах, можно использовать например для отслеживания готовности очередного журнала с логами.
Читаем xcactivitylog
Итак, файл лога представляет собой сжатый gzip журнал, названием служит уникальный идентификатор UUID.
После распаковки получаем журнал, записанный в формате сериализации SLF0.
Пример распакованного журнала в формате SLF0
SLF010#21%IDEActivityLogSection1@0#39"Xcode.IDEActivityLogDomainType.BuildLog25"Build XCActivityLogParser212"eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9cbbac35a7833c541^0000007fc3632d42^1(1@1#27"com.apple.dt.IDE.LogSection16"Prepare packages212"eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9f73bc45a7833c541^4303c95a7833c541^---0#0#0#46"Compile plug-ins and run any prebuild commands--36"52BE500F-D551-461D-975D-BF4B4AA236BF--0"0(0#0#0#---36"2976A337-D8BA-4626-B5F2-41F0F7CB232E--
На просторах сети нет официальной документации, описывающий данный вид сериализации. Все, что удалось найти - плод трудов энтузиастов, за что им большое спасибо.
Каждый лог начинается с обязательного хедера SLF0.
Далее последовательность токенов в следующем формате:
<side_value><delimiter><side_value>
<side_value> - опциональное значение, и зависит от конкретного разделителя.
Текущая версия SLF0 поддерживает 7 разделителей, каждый из которых является описанием значения конкретного типа:
# integer
Описывает тип integer, например:
10#
Значение слева: UInt64, собственно само значение токена.
Значение справа: отсутствует.
" string
Описывает тип string, например:
21"IDEActivityLogSection
Значение слева: UInt64, описывает количество символов, которое идет справа от разделителя и является значением строкового токена. В данном случае это значит, что искомым строковым значением является строка справа, состоящая из 21 символа. Подсчет символов ведется в utf-16, и не соответствует дефолтному count у экземпляров типа string, который возвращает количество графем).
Значение справа: строка, состоящая из количества символов, которое находится слева от разделителя.
^ double
Описывает тип double, например:
4fcbedd82b32c541^
Значение слева: представляет собой число с плавающей запятой с прямым порядком байтов, закодированное в шестнадцатеричном формате. Используется в журнале для представления типа timeInterval.
Пример приведения к обычному double из языка swift:
guard let integerValue = UInt64("4fcbedd82b32c541", radix: 16) else { exit(0) }
let double = Double(bitPattern: integerValue.byteSwapped)
print(double) // 711219121.857767
Значение справа: отсутствует.
- null
Описывает null значение, т.е. значения какого-либо поля у нас просто нет, например:
-
Значение слева: отсутствует.
Значение справа: отсутствует.
( array
Описывает array, указывая количество элементов, которые тот содержит, например:
2(
Значение слева: количество элементов в массиве. Элементами массива являются значения с типом class_instance, о них будет чуть ниже.
Значение справа: отсутствует.
% class_name
Описывает class_name, в SLF0 решающим фактором успеха является порядок всех токенов в журнале, при парсинге их порядок важно соблюсти. Полученная индексация class_name - искомая при парсинге class_instance.
38%IDEActivityLogCommandInvocationSection
Значение слева: здесь все по аналогии с типом string, который описан выше.
Значение справа: название класса.
@ class_instance
Описывает class_instance, т.е. указывает на название класса, исходя из которого должно стать понятно, как интерпретировать все токены, которые будут следовать далее за этим class_instance.
1@
Значение слева: UInt64, собственно само значение токена, указывающее на позицию соответствующего class_name в журнале (требуется, чтобы понять к какому типу относятся токены, которые идут далее).
Значение справа: отсутствует.
Для удобства понимания данного языка сериализации, набросал описание синтаксиса в виде формы Бэкуса-Наура (может пригодиться при разработке соответствующего синтаксического анализатора):
<header> := SLF0
<integer_delimiter> := #
<double_delimiter> := ^
<null_delimiter> := -
<string_delimiter> := "
<array_delimiter> := (
<class_name_delimiter> := %
<class_instance_delimiter> := @
<delimiter> := <integer_delimiter>|<double_delimiter>|<null_delimiter>|<string_delimiter>|<array_delimiter>|<class_name_delimiter>|<class_instance_delimiter>
<side_value> := <character>|<digit>|<side_value><character>| <side_value><digit>
<value> := [<side_value>]<delimiter>[<side_value>]
<log> := <value>|<log><value>
<all_log> := <header><log>
Единственное, расписывать что такое <digit> и <character> не стал, думаю и так понятно.
Итак, зная все вышеперечисленные синтаксические и семантические правила, попробуем прочитать какой-нибудь конкретный лог (из примера выше), после чтения получаем следующий список токенов, идущих один за одним (использую написанный tokenizer):
Пример полученных токенов xcactivitylog
integer(10)
class_name("IDEActivityLogSection")
class_instance(1)
integer(0)
string("Xcode.IDEActivityLogDomainType.BuildLog")
string("Build XCActivityLogParser")
string("eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9")
double(711389365.529138)
double(63113904000.0)
array(1)
class_instance(1)
integer(1)
string("com.apple.dt.IDE.LogSection")
string("Prepare packages")
string("eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9")
double(711389365.53308)
double(711389365.570412)
null
null
null
integer(0)
integer(0)
integer(0)
string("Compile plug-ins and run any prebuild commands")
null
null
string("52BE500F-D551-461D-975D-BF4B4AA236BF")
null
null
string("")
array(0)
integer(0)
integer(0)
integer(0)
null
null
null
string("2976A337-D8BA-4626-B5F2-41F0F7CB232E")
null
null
На первый взгляд, все очень страшно и не менее понятно, чем было до этого. Однако, попробуем все же разобраться.
Для начала, прошу обратить внимание на имена классов, на самом деле их ограниченное количество, на момент написания статьи:
IDEActivityLogSection
IDEActivityLogCommandInvocationSection
IDEActivityLogUnitTestSection
IDEActivityLogMajorGroupSection
IDEActivityLogMessage
DVTDocumentLocation
DVTTextDocumentLocation
При попытке найти информацию о вышеперечисленных типах, становится понятно, что все они описаны в приватном фреймворке IDEFoundation.framework, который является частью Xcode и по умолчанию находится по адресу:
open /Applications/Xcode.app/Contents/Frameworks/IDEFoundation.framework/Versions/A/
Далее, посредством Reverse engineering можно все эти классы отыскать и воспроизвести их набор полей, для последующего сопоставления со значениями токенов, полученных выше (все производимые манипуляции - в исследовательских целях).
Ради интереса я покопался с ktool и смог без особого труда получить описание всех классов:
ktool dump --headers /Applications/Xcode.app/Contents/Frameworks/IDEFoundation.framework/Versions/A/IDEFoundation
Приведу в пример IDEActivityLogSection, ради удобства - только его инициализатор, который отражает все нужные нам поля:
-(id)initWithSectionType:(NSInteger)arg0
domainType:(id)arg1
title:(id)arg2
subtitle:(id)arg3
location:(id)arg4
signature:(id)arg5
timeStartedRecording:(CGFloat)arg6
timeStoppedRecording:(CGFloat)arg7
subsections:(id)arg8
text:(id)arg9
messages:(id)arg10
wasCancelled:(char)arg11
wasFetchedFromCache:(char)arg12
commandDetailDescription:(id)arg13
resultCode:(NSInteger)arg14
uniqueIdentifier:(id)arg15
localizedResultString:(id)arg16
xcbuildSignature:(id)arg17
Единственная проблема, что порядок токенов не соответствует порядку, полученному при исследовании фреймворка.
Однако, ребята из тулзы XCLogParser уже все нашли и сопоставили, большое им спасибо, как выглядят все полученные типы с правильным порядком полей, можно посмотреть здесь.
К примеру, итоговые поля с верным порядком для IDEActivityLogSection :
public let sectionType: Int8
public let domainType: String
public let title: String
public let signature: String
public let timeStartedRecording: Double
public var timeStoppedRecording: Double
public var subSections: [IDEActivityLogSection]
public let text: String
public let messages: [IDEActivityLogMessage]
public let wasCancelled: Bool
public let isQuiet: Bool
public var wasFetchedFromCache: Bool
public let subtitle: String
public let location: DVTDocumentLocation
public let commandDetailDesc: String
public let uniqueIdentifier: String
public let localizedResultString: String
public let xcbuildSignature: String
Зная все это, попробуем расшифровать полученные токены:
Первый токен - всегда версия формата сериализации SLF0, в нашем случае 10-я:
integer(10) // Версия SLF0
Далее идет первое объявление имени типа, на которое будут ссылаться токены с типом class_instance:
class_name("IDEActivityLogSection") // Название класса (нужно для понимания, к какому типу относятся поля у class_instance)
Ниже начинается описание первого объекта со значениями его параметров, class_instance(1) указывает, что следующие токены следует интерпретировать как class_name, который указан под соответствующим относительным индексом 1, в нашем случае - IDEActivityLogSection:
class_instance(1) // Указывает, что объект типа IDEActivityLogSection
integer(0) // sectionType
string("Xcode.IDEActivityLogDomainType.BuildLog") // domainType
string("Build XCActivityLogParser") // title
string("eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9") // signature
double(711389365.529138) // timeStartedRecording (TimeInterval)
double(63113904000.0) // timeStoppedRecording (TimeInterval)
Следом идет объявление массива, за которым идет описание его элементов:
array(1) // Массив из одного элемента
class_instance(1) // Элемент массива, также типа IDEActivityLogSection
integer(1) // sectionType
string("com.apple.dt.IDE.LogSection") // domainType
string("Prepare packages") // title
string("eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9")
double(711389365.53308) // timeStartedRecording (TimeInterval)
double(711389365.570412) // timeStoppedRecording (TimeInterval)
null // subSections
null // text
null // messages
integer(0) // wasCancelled
integer(0) // isQuiet
integer(0) // wasFetchedFromCache
string("Compile plug-ins and run any prebuild commands") // subtitle
null // location
null // commandDetailDesc
string("52BE500F-D551-461D-975D-BF4B4AA236BF") // uniqueIdentifier
null // localizedResultString
null // xcbuildSignature
И, напоследок, оставшиеся поля у корневой секции:
string("") // text
array(0) // messages
integer(0) // wasCancelled
integer(0) // isQuiet
integer(0) // wasFetchedFromCache
null // subtitle
null // location
null // commandDetailDesc
string("2976A337-D8BA-4626-B5F2-41F0F7CB232E") // uniqueIdentifier
null // localizedResultString
null // xcbuildSignature
Для удобства понимания, итоговой парсинг журнала, записанным в формате json:
{
"version": 10,
"mainSection": {
"sectionType": 0,
"domainType": "Xcode.IDEActivityLogDomainType.BuildLog",
"title": "Build XCActivityLogParser",
"signature": "eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9",
"timeStartedRecording": 711389365.529138,
"timeStoppedRecording": 63113904000.0,
"subSections": [
{
"sectionType": 1,
"domainType": "com.apple.dt.IDE.LogSection",
"title": "Prepare packages",
"signature": "eyJ0eXBlIjp7ImJsdWVwcmludFByb3ZpZGVyIjp7fX0sImJsdWVwcmludFByb3ZpZGVyX3Byb3ZpZGVyRmlsZVBhdGhTdHJpbmciOiJcL1VzZXJzXC92b3JvYnlvdlwvRG9jdW1lbnRzXC9YQ0FjdGl2aXR5TG9nUGFyc2VyXC9YQ0FjdGl2aXR5TG9nUGFyc2VyLnhjb2RlcHJvaiJ9",
"timeStartedRecording": 711389365.53308,
"timeStoppedRecording": 711389365.570412,
"subSections": null,
"text": null,
"messages": null,
"wasCancelled": false,
"isQuiet": false,
"wasFetchedFromCache": false,
"subtitle": "Compile plug-ins and run any prebuild commands",
"location": null,
"commandDetailDesc": null,
"uniqueIdentifier": "52BE500F-D551-461D-975D-BF4B4AA236BF",
"localizedResultString": null,
"xcbuildSignature": null
}
],
"text": "",
"messages": [],
"wasCancelled": false,
"isQuiet": false,
"wasFetchedFromCache": false,
"subtitle": null,
"location": null,
"commandDetailDesc": null,
"uniqueIdentifier": "2976A337-D8BA-4626-B5F2-41F0F7CB232E",
"localizedResultString": null,
"xcbuildSignature": null
}
}
Собственно, это все, что я хотел рассказать. В полученном, удобочитаемом виде можно лог исследовать и вычленить ту информацию, которая может быть вам полезна в своих проектах.
Спасибо за внимание!
Полезные ссылки:
https://github.com/MobileNativeFoundation/XCLogParser/blob/master/docs/Xcactivitylog Format.md
https://speakerdeck.com/iosdevelopersmexico/xclogparser-switui-primeras-impresiones