installshield - Windows Installer runs custom action code not in the right sequence and fails -

i have weird situation custom action code not run synchronically.
in log can see "winroot dir" log line should appear after "commonfiles dir" line. appears @ end.

this code:

[customaction]     public static actionresult ccca_logproductname(session session)     {         productname = session[installshieldconstants.productname];         customactiondata customactiondata = new customactiondata();          // log properties         cculog.logmessagetofile(session, "ccca_logproductname", "installdir : " +                                 session[installshieldconstants.installdir]);         cculog.logmessagetofile(session, "ccca_logproductname", "product version : " +                                session[installshieldconstants.productversion]);         cculog.logmessagetofile(session, "ccca_logproductname", "source dir : " +                                session[installshieldconstants.sourcedir]);         cculog.logmessagetofile(session, "ccca_logproductname", "support dir : " +                                session[installshieldconstants.supportdir]);         cculog.logmessagetofile(session, "ccca_logproductname", "commonfiles dir : " +                                environment.getenvironmentvariable("commonprogramfiles"));         cculog.logmessagetofile(session, "ccca_logproductname", "winroot dir : " +                                session[installshieldconstants.windowsvolumedir]);          customactiondata.add(installshieldconstants.productname, productname);         session["ccca_logproductnameonfirsttimeinstallstart"] = customactiondata.tostring();         session["ccca_logproductnameonuninstallstart"] = customactiondata.tostring();         session["ccca_logproductnameonuninstallend"] = customactiondata.tostring();         session["ccca_logproductnameoninstallstart"] = customactiondata.tostring();         session["ccca_logproductnameoninstallend"] = customactiondata.tostring();          return actionresult.success;     } 

while log indicates following:

calling custom action cosmopublishercustomactions!cosmopublishercustomactions.ccucustomactions.ccca_logproductname 07/23/2015 11:24:44 :: cosmopublisher:: ccca_logproductname :: installdir : c:\program files (x86)\cosmocom\server components\ 07/23/2015 11:24:44 :: cosmopublisher:: ccca_logproductname :: product version : 7.2.0.119 07/23/2015 11:24:44 :: cosmopublisher:: ccca_logproductname :: source dir : c:\program files (x86)\cosmocom\server components\cosmopublisherhotfixes\hf72-40106\ 07/23/2015 11:24:44 :: cosmopublisher:: ccca_logproductname :: support dir : c:\users\svccos~1\appdata\local\temp{d3407c75-8846-4db4-8736-149a884053ef} 07/23/2015 11:24:44 :: cosmopublisher:: ccca_logproductname :: commonfiles dir : c:\program files (x86)\common files msi (s) (c4!70) [11:24:44:641]: property change: adding ccca_logproductnameonfirsttimeinstallstart property. value 'productname=media services .net'. msi (s) (c4!70) [11:24:44:642]: property change: adding ccca_logproductnameonuninstallstart property. value 'productname=media services .net'. msi (s) (c4!70) [11:24:44:642]: property change: adding ccca_logproductnameonuninstallend property. value 'productname=media services .net'. msi (s) (c4!70) [11:24:44:642]: property change: adding ccca_logproductnameoninstallstart property. value 'productname=media services .net'. msi (s) (c4!70) [11:24:44:642]: property change: adding ccca_logproductnameoninstallend property. value 'productname=media services .net'. 07/23/2015 11:24:44 :: cosmopublisher:: ccca_logproductname :: winroot dir : c:\ customaction ccca_logproductname returned actual error code 1603 (note may not 100% accurate if translation happened inside sandbox) action ended 11:24:44: ccca_logproductname. return value 3. action ended 11:24:44: install. return value 3.

my installshield custom action set 'synchronous' can't understand why happening. weird custom action log file fails.

edit:
log function writes session log , local file:

/// <summary>     /// writing message log file     /// </summary>     /// <param name="tag">tag of log message.</param>     /// <param name="message">message write log.</param>     public static void logmessagetofile(session session, string tag, string message)     {         streamwriter sw = file.appendtext(             gettemppath() + logfilename);         try         {             string logline = string.format(                 "{0:g} :: {1} :: {2}", datetime.now, tag, message);             sw.writeline(logline);             session.log("{0:g} :: {1}:: {2} :: {3}", datetime.now, logtag, tag, message);         }                 {             sw.close();         }     }   

i'm curious why don't see stack trace dtf. dtf allows attach debugger, i'm sure commands running in right order. i've never seen msi log out of order it's possible. try /l*v! (emphasis on ! ) see if makes difference in order it's surfaced.

the simplest of cas can fail. that's why it's important master of them or don't them @ all.