V krátkosti se podělím o svůj poslední debugging zážitek – ani ne proto, že by byl výjimečný svým zjištěním, ale spíše jako inspiraci pro techniky a postupy, které lze při debuggingu použít.
Symptom
Problém se projevoval tím, že z Azure WebJobs Dashboardu (Kudu) se nám nedařilo spouštět funkci, které jsme potřebovali jako vstupní parametr předat hodnotu typu DateTime:
Spuštění končilo chybou System.FormatException: String was not recognized as a valid DateTime:
![clip_image002[5]](https://knowledge-base.havit.cz/wp-content/uploads/2016/06/clip_image0025.jpg?w=738&h=768 "clip_image002[5]")
Architektura řešení
WebJobs SDK umožňuje, abyste vytvořili WebJob, který v sobě má funkce (Functions). Tyto mohou být spouštěny podle časového plánu, triggerovány událostí na straně Azure (např. nová message v Queue, nový soubor na disku, nový záznam v DB tabulce, atp.), nebo spouštěny ručně pomocí UI Azure WebJobs Dashboardu (součást Kudu, resp. jeho automatické rozšíření).
V našem případě se jednalo o ruční spouštění funkce z Azure WebJobs Dashboardu, které na pozadí funguje tak, že s WebJobs hostem (vaším procesem – WebJobem – který v sobě má aktivní JobHost z WebJobs SDK) komunikuje prostřednictvím Azure Queue.
1. Kontrola formátu data na vstupu
Na začátku člověk samozřejmě pochybuje o tom nejjednodušším – tedy jestli zadává do UI WebJobs Dashboardu hodnotu ve správném formátu. Je to samozřejmě webový formulář, který musí string zapsaný do textboxu nějak parsovat na DateTime.
Hledal jsem tedy ve zdrojácích WebJob SDK (GitHub), jak se vstup na DateTime převádí. Protože už jsem sám implementoval binding vlastního typu (aby bylo možno pohodlně volat z UI funkci, která potřebuje typ na vstupu), celkem rychle jsem se donavigoval na StringToDateTimeConverter, ve kterém je
public DateTime Convert(string input)
{
return DateTime.ParseExact(input, "O", CultureInfo.InvariantCulture,
DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal);
}
Aby si ověřil, že mám správnou podobu vstupu, použil jsem nový C# Interactive z Visual Studia 2015 (stejně snadno by pomohl i LINQPad):
…zde tedy zakopaný pes nebude, vstup máme správně.
2. Zjištění, jaký string vstupuje do konverze DateTime.ParseExact
Metoda DateTime.ParseExact(..) je poměrně přísná na vstupní formát. Vadí jí i trailing whitespace a podobné “drobnosti”, tedy jsem se vydal cestou zjišťování, co do této metody vstupuje, a kde se to po cestě “pokazí”.
Bohužel situace není úplně jednoduchá – WebJobs SDK a jeho komunikace s Dashboardem nám zde běží v prostředí Azure a není úplně triviální vše napojit z lokálního prostředí a debugovat klasicky ve Visual Studiu (byť by asi nebyl problém lokální instanci nasměrovat na příslušný Azure Storage Account). Nechtělo se mi řešit tuto cestu, která by mi stejně umožnila ladění jen na straně WebJobs hosta, vydal jsem přes analýzu produkčního prostředí Azure.
Mým prvním cílem bylo získat memory-dump WebJobs hosta a zkusit v něm najít, jaký string se parsuje. Vzhledem k tomu, že můj WebJobs host nebyl v danou chvíli zatížen jinou aktivitou, nezdržoval jsem se nastavováním podmínek, za kterých chci memory-dump sejmout (např. při výjimce FormatException, nebo bych mohl zvolit breakpoint do metody Convert, atp.). Rozhodl jsem se to risknout, použít prostý ručně sejmutý memory-dump a doufat, že Garbage Collector mi příslušné instance ještě z paměti nevyhodil, a že v něm něco najdu.
Pro prohledávání memory-dumpu se výborně hodí NetExt rozšíření WinDbg se svým !wfrom:
0:000> .symfix 0:000> .reload 0:000> .load c:\Windows\Microsoft.NET\Framework\v4.0.30319\sos 0:000> .load netext 0:000> !wfrom -type System.String where ( $contains($string(),"2016-05-14") ) select $addr(), $string() 0 Object(s) listed 71,537 Object(s) skipped by filter
…nicméně žádný řetězec, který by v sobě měl “2016-05-14” se v paměti nenašel.
Nenechal jsem se odradit (byť už jsem podezíral GC) a zkusil hledat jen “2016”:
0:000> !wfrom -type System.String where ( $contains($string(),"2016") ) select $addr(), $string() .. calculated: 05/14/2016 15:05:23 +02:00 calculated: 0737EC64 calculated: 05/14/2016 15:05:23 +02:00 calculated: 073C1E58 ... 50 Object(s) listed 71,487 Object(s) skipped by filter
…padesát stringů s “2016” nalezeno (výpis zkrácen) a mezi nimi i dva, které mě velmi zajímaly. Jsou to přesně moje vstupní hodnoty, jenom jinak formátovány. Evidentně se jedná o stringy, které se DateTime.ParseExact(…) snažil neúspěšně parsovat.
3. Zjišťování, kde se stringová reprezentace data a času změní
V tuto chvíli již bylo více než pravděpodobné, že se jedná o bug ve WebJobs SDK, nicméně mi to nedalo, abych se v tom nepovrtal dále. Chtěl jsem co nejlépe lokalizovat místo, kde dojde k poničení stringu s datem.
Procházel jsem tedy ve zdrojových kóde WebJobs SDK cestu, kterou tečou argumenty od UI Dashboardu (FunctionController.cs – GetArguments(), Invoke()), přes odesílání zprávy do Azure Queue (HostMessaging/Invoker.cs) a dále.
Protože jsem měl k dispozici memory dump WebJobs Hosta, který z Azure Queue naopak zprávy vyzvedává a vykonává, chtěl jsem zkontrolovat, jakou zprávu z queue vyzvedne a jestli už v ní jsou argumenty poškozeny. Ze zdrojových kódů je zřejmé, že komunikace proběhne zasláním zprávy typu CallAndOverrideMessage, která v sobě má IDictionary<string, string> argumentů. Použil jsem tedy !DumpHeap s filtrem na typ a následně i !wdict z NetExt pro přehledné vypsání obsahu Dictionary:
0:000> !DumpHeap -type CallAndOverrideMessage
Address MT Size
01e17eb4 060223fc 60
01e18448 06073050 56
07380594 06073050 56
073c2d78 060223fc 60
Statistics:
...
0:000> !do 01e17eb4
Name: Microsoft.Azure.WebJobs.Host.Protocols.CallAndOverrideMessage
MethodTable: 060223fc
EEClass: 06018c14
Size: 60(0x3c) bytes
File: D:\local\Temp\jobs\continuous\JobScheduler\3pfsjnlr.4ry\Microsoft.Azure.WebJobs.Host.dll
Fields:
MT Field Offset Type VT Attr Value Name
72cbd834 4000001 4 System.String 0 instance 01e17d4c <Type>k__BackingField
72cba91c 4000018 14 System.Guid 1 instance 01e17ec8 <Id>k__BackingField
72cbd834 4000019 8 System.String 0 instance 01e17d78 <FunctionId>k__BackingField
7289231c 400001a c ...tring, mscorlib]] 0 instance 01e17ef0 <Arguments>k__BackingField
06022340 400001b 10 System.Int32 1 instance 2 <Reason>k__BackingField
72c6cb20 400001c 24 ....Guid, mscorlib]] 1 instance 01e17ed8 <ParentId>k__BackingField
0:000> !wdict 01e17ef0
Items : 3
[0]:==============================================(Physical Index: 2)
System.__Canon key = 01e17e98 dateTo
System.__Canon value = 01e1816c 05/14/2016 15:05:23 +02:00
[1]:==============================================(Physical Index: 0)
System.__Canon key = 01e17e34 businessKind
System.__Canon value = 01e17e5c Onshore
[2]:==============================================(Physical Index: 1)
System.__Canon key = 01e17e78 dateFrom
System.__Canon value = 01e17f80 05/14/2016 15:05:23 +02:00
Zde se ukázalo, že příchozí zpráva z Azure Queue, resp. její deserializace už v sobě chybný změněný formát data má.
Nedalo mi to a hledal jsem, co přesně teče přes Azure Queue. Chvilku jsem se marně snažil zachytit zprávu ve Visual Studiu přes Cloud Explorer, až jsem se nakonec vrátil ke zdrojovým kódům WebJobs SDK a jejich implementaci příjmu zpráv z Azure Queue přes StorageQueueMessage, která v sobě (resp. přes CloudQueueMessage z Azure Storage) drží raw-stringovou reprezentaci zprávy:
0:000> !DumpHeap -type CloudQueueMessage /d
Address MT Size
0134bae0 057d7fa0 12
01404e24 05b30b38 12
01404e30 05b31034 12
01459908 04ada834 32
01459e2c 04add3c0 12
01459e90 04adac64 32
01e17b34 05b30e58 80
0734bd5c 05b30e58 80
07473d64 05b30e58 80
Statistics:
...
0:000> !DumpObj /d 07473d64
Name: Microsoft.WindowsAzure.Storage.Queue.CloudQueueMessage
MethodTable: 05b30e58
EEClass: 057c4180
Size: 80(0x50) bytes
File: D:\local\Temp\jobs\continuous\JobScheduler\3pfsjnlr.4ry\Microsoft.WindowsAzure.Storage.dll
Fields:
MT Field Offset Type VT Attr Value Name
72cbd834 4000141 4 System.String 0 instance 07473828 <Id>k__BackingField
72cbd834 4000142 8 System.String 0 instance 07473880 <PopReceipt>k__BackingField
72c696f4 4000143 1c ...ffset, mscorlib]] 1 instance 07473d80 <InsertionTime>k__BackingField
72c696f4 4000144 2c ...ffset, mscorlib]] 1 instance 07473d90 <ExpirationTime>k__BackingField
72c696f4 4000145 3c ...ffset, mscorlib]] 1 instance 07473da0 <NextVisibleTime>k__BackingField
72cbf6bc 4000146 14 System.Int32 1 instance 1 <DequeueCount>k__BackingField
05b30da4 4000147 18 System.Int32 1 instance 1 <MessageType>k__BackingField
72cbd834 4000148 c System.String 0 instance 074738c8 <RawString>k__BackingField
72cc2518 4000149 10 System.Byte[] 0 instance 00000000 <RawBytes>k__BackingField
72cbab18 400013f 150 System.TimeSpan 1 static 021f4f28 MaximumTimeToLive
72cba5a0 4000140 154 ...Text.UTF8Encoding 0 static 0734bfb4 utf8Encoder
0:000> !DumpObj /d 074738c8
Name: System.String
MethodTable: 72cbd834
EEClass: 728ff344
Size: 1166(0x48e) bytes
File: D:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: ew0KICAiVHlwZSI6ICJDYWxsQW5kT3ZlcnJpZGUiLA0KICAiSWQiOiAiMmExYzYwNjMtNmFkZC00MmE1LWE1M2EtNjZhYmM2MTY3NmI5IiwNCiAgIkZ1bmN0aW9uSWQiOiAiSGF2aXQuWGVyb3hXZWJUb29sLkpvYlNjaGVkdWxlci5Kb2JzLkVycFN5bmMuUXVlcmllc0Rvd25sb2FkRXJwU3luY0pvYi5FeGVjdXRlRGF0ZVJhbmdlIiwNCiAgIkFyZ3VtZW50cyI6IHsNCiAgICAiYnVzaW5lc3NLaW5kIjogIk9uc2hvcmUiLA0KICAgICJkYXRlRnJvbSI6ICIyMDE2LTA1LTE0VDE1OjA1OjIzLjk4ODA4MTQrMDI6MDAiLA0KICAgICJkYXRlVG8iOiAiMjAxNi0wNS0xNFQxNTowNToyMy45ODgwODE0KzAyOjAwIg0KICB9LA0KICAiUmVhc29uIjogIkRhc2hib2FyZCIsDQogICJQYXJlbnRJZCI6ICJiYjQyYWYwYS00MTcyLTRiYjUtYTRiMS01ZThiMzQwMDU1MDkiDQp9
Fields:
MT Field Offset Type VT Attr Value Name
72cbf6bc 4000243 4 System.Int32 1 instance 576 m_stringLength
72cbe278 4000244 8 System.Char 1 instance 65 m_firstChar
72cbd834 4000248 40 System.String 0 shared static Empty
>> Domain:Value 0095f5d0:NotInit <<
Ze zdrojových kódů Azure Storage CloudQueueMessage.AsString je zřejmé, že v RawString je base64, který snadno převedeme pomocí https://www.base64decode.org/:
…zde se překvapivě ukazuje, že JSON serializace zprávy má v sobě korektní (původní) podobu data, a že problém tedy je v konverzi z CloudQueueMessage, resp. StorageQueueMessage na CallAndOverrideMessage. Ve zdrojácích už nebyl problém dohledat, že se tak děje v HostMessageExecutor pomocí JsonConvert deserializace:
HostMessage model = JsonConvert.DeserializeObject<HostMessage>(value.AsString, JsonSerialization.Settings); CallAndOverrideMessage callAndOverrideModel = model as CallAndOverrideMessage;
4. Neumí tedy Newtonsoft Json.NET správně deserializovat string?
WebJobs SDK používá pro HostMessage customizovaný JsonConvertor, při jehož použití se poškození stringu s datem projeví. Pokud se convertor odebere a ponechá se výchozí serializace+deserializace, problém se neprojeví.
Více do hloubky už jsem nešel, protože písmenko “J” na začátku názvu vývojářské technologie je pro mě bránou do pekla, kterou jsem nechtěl projít. Ke problému jsem vytvořil jednoduché repro a nareportoval issue WebJobs SDK týmu.
HAVIT Knowledge Base 