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:

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.

Po prvním neúspěšném pokusu s Kudu Process Explorerem, který mi sejmul bezcenný 64-bitový dump mého 32-bitového procesu, jsem získal dump přes Debug Consoli spuštěním SysInternals ProcDump (viz samostatný post).

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.