search

DragonBox / u3d

U3d is a cross-platform set of tools to interact with Unity3D from command line.
MIT License
361 stars 33 forks source link

unity appears to rewrite log file when using -logFile argument #3

Open lacostej opened 7 years ago

lacostej commented 7 years ago

running the Example2 leads to some weird lines added at the top of the editor AFTER process started:

Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools64/JobProcess
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_5.6.1f1/Unity.app/Contents/Tools/UnityShaderCompiler

Tested on Mac with Unity 5.6.1f1

Reported as 939108 on Unity side

lacostej commented 7 years ago

Executing examples/Example2 from the CLI using 5.6.1f1 on Mac gives different log contents

Here's a cleaned diff:

--- /dev/fd/63  2017-08-03 17:12:29.000000000 +0200
+++ /dev/fd/62  2017-08-03 17:12:29.000000000 +0200
@@ -1,7 +1,11 @@
+setrlimit() failed with errno=1
+Initialize mono
+Mono path[0] = '/Applications/Unity_5.6.1f1/Unity.app/Contents/Managed'
+Mono path[1] = '/Applications/Unity_5.6.1f1/Unity.app/Contents/Mono/lib/mono/2.0'
+Mono config path = '/Applications/Unity_5.6.1f1/Unity.app/Contents/Mono/etc'
+Using monoOptions --debugger-agent=transport=dt_socket,embedding=1,defer=y,address=0.0.0.0:...
 ... Unity[...] NSDocumentController Info.plist warning: The values of CFBundleTypeRole entries must be 'Editor', 'Viewer', 'None', or 'Shell'.
 ...300157 bytes written to /Users/lacostej/Library/Unity/Certificates/CACerts.pem
-.app/Contents/Mono/etc'
-Using monoOptions --debugger-agent=transport=dt_socket,embedding=1,defer=y,address=0.0.0.0:...

 LICENSE SYSTEM [...] Next license update check is after...

@@ -9,8 +13,6 @@

  COMMAND LINE ARGUMENTS:
 /Applications/Unity_5.6.1f1/Unity.app/Contents/MacOS/Unity
--logFile
-./editor_5.6.1f1.log
 -executeMethod
 U3d.EditorRun.Build
 -quit

This is reproduced by doing

version=2017.1.0f3

/Applications/Unity_$version/Unity.app/Contents/MacOS/Unity -projectPath `pwd` -logFile ./editor_$version.log -executeMethod U3d.EditorRun.Build -quit -batchmode
/Applications/Unity_$version/Unity.app/Contents/MacOS/Unity -projectPath `pwd` -executeMethod U3d.EditorRun.Build -quit -batchmode
cp ~/Library/Logs/Unity/Editor.log ./editor_${version}_raw.log

u3dlogdiff.sh editor_5.6.1f1.log editor_5.6.1f1_raw.log

(see #10 for u3dlogiff)

So we cannot rely on Initialize mono being there.

Still working on the errors appearing at the top.

lacostej commented 7 years ago

I tested more with 2017.1.0f3 on mac. I reproduce the overwriting of the top of the file when using the -logFile argument:

 COMMAND LINE ARGUMENTS:
/Applic[usbmuxd] Start listen thread
[usbmuxd] Listen thread started
[usbmuxd] Send listen message
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/JobProcess
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
Launching external process: /Applications/Unity_2017.1.0f3/Unity.app/Contents/Tools/UnityShaderCompiler
debugger-agent: Unable to listen on 29
[usbmuxd] Stop listen thread
[usbmuxd] Error: 
[usbmuxd] Listen thread exiting

On other side this behaves properly

version=2017.1.0f3
/Applications/Unity_$version/Unity.app/Contents/MacOS/Unity -projectPath `pwd` -logFile /dev/stdout -executeMethod U3d.EditorRun.Build -quit -batchmode > editor_${version}_piped.log
setrlimit() failed with errno=1
2017-08-03 20:21:46.196 Unity[50887:2615825] NSDocumentController Info.plist warning: The values of CFBundleTypeRole entries must be 'Editor', 'Viewer', 'None', or 'Shell'.
...300157 bytes written to /Users/lacostej/Library/Unity/Certificates/CACerts.pem

LICENSE SYSTEM [201783 20:21:46] No start/stop license dates set

LICENSE SYSTEM [201783 20:21:46] Next license update check is after 2017-08-04T16:43:38

DisplayProgressbar: Unity license

 COMMAND LINE ARGUMENTS:
/Applications/Unity_2017.1.0f3/Unity.app/Contents/MacOS/Unity
-projectPath
/Users/lacostej/Code/WWTK/u3d/examples/Example2
-logFile
/dev/stdout
-executeMethod
U3d.EditorRun.Build
-quit
-batchmode
lacostej commented 6 years ago

I followed this issue a bit.

Unity partially fixed this in 2017.1.1f1. From that version and above, when using the -logFile argument, the out of order messages are not written to the top of the logfile, but instead either added at the proper moment, or sent to the error output of the Unity process (something entirely new).

When not using the -logFile argument, the output is sent as expected to the main editor log file.

Here's the script I used to check things and its output

versions=( 5.6.5f1 2017.1.0f3 2017.1.1f1 2017.1.2f1 2017.1.3f1 2017.2.1f1 2017.3.0f2 )

rm -f editor*.log

for version in "${versions[@]}"; do
  echo "Using version $version"
  git checkout -- .
  /Applications/Unity_$version/Unity.app/Contents/MacOS/Unity -projectPath `pwd` -logFile ./editor_${version}_arg.log -executeMethod U3d.EditorRun.Build -quit -batchmode 2&> ./editor_${version}_err.log

  git checkout -- .

  /Applications/Unity_$version/Unity.app/Contents/MacOS/Unity -projectPath `pwd` -executeMethod U3d.EditorRun.Build -quit -batchmode

  cp ~/Library/Logs/Unity/Editor.log ./editor_${version}_raw.log

  git checkout -- .

  u3d -u $version -- -projectPath `pwd` -executeMethod U3d.EditorRun.Build -quit -batchmode -logFile ./editor_${version}_u3d_arg.log
done
-rw-r--r--  1 lacostej  staff  157890 Apr 19 22:42 editor_5.6.5f1_arg.log
-rw-r--r--  1 lacostej  staff       0 Apr 19 22:42 editor_5.6.5f1_err.log
-rw-r--r--  1 lacostej  staff   88309 Apr 19 22:43 editor_5.6.5f1_raw.log
-rw-r--r--  1 lacostej  staff   87479 Apr 19 22:43 editor_5.6.5f1_u3d_arg.log
-rw-r--r--  1 lacostej  staff  189894 Apr 19 22:43 editor_2017.1.0f3_arg.log
-rw-r--r--  1 lacostej  staff       0 Apr 19 22:43 editor_2017.1.0f3_err.log
-rw-r--r--  1 lacostej  staff  104279 Apr 19 22:43 editor_2017.1.0f3_raw.log
-rw-r--r--  1 lacostej  staff  103400 Apr 19 22:43 editor_2017.1.0f3_u3d_arg.log
-rw-r--r--  1 lacostej  staff  159037 Apr 19 22:44 editor_2017.1.1f1_arg.log
-rw-r--r--  1 lacostej  staff     806 Apr 19 22:44 editor_2017.1.1f1_err.log
-rw-r--r--  1 lacostej  staff   97400 Apr 19 22:44 editor_2017.1.1f1_raw.log
-rw-r--r--  1 lacostej  staff   96694 Apr 19 22:44 editor_2017.1.1f1_u3d_arg.log
-rw-r--r--  1 lacostej  staff  191931 Apr 19 21:43 editor_2017.1.2f1_arg.log
-rw-r--r--  1 lacostej  staff     977 Apr 19 21:43 editor_2017.1.2f1_err.log
-rw-r--r--  1 lacostej  staff  104821 Apr 19 21:43 editor_2017.1.2f1_raw.log
-rw-r--r--  1 lacostej  staff  103947 Apr 19 21:43 editor_2017.1.2f1_u3d_arg.log
-rw-r--r--  1 lacostej  staff  169828 Apr 19 21:43 editor_2017.1.3f1_arg.log
-rw-r--r--  1 lacostej  staff     977 Apr 19 21:43 editor_2017.1.3f1_err.log
-rw-r--r--  1 lacostej  staff  103741 Apr 19 21:43 editor_2017.1.3f1_raw.log
-rw-r--r--  1 lacostej  staff  102865 Apr 19 21:44 editor_2017.1.3f1_u3d_arg.log
-rw-r--r--  1 lacostej  staff  91549 Apr 19 21:44 editor_2017.2.1f1_arg.log
-rw-r--r--  1 lacostej  staff    823 Apr 19 21:44 editor_2017.2.1f1_err.log
-rw-r--r--  1 lacostej  staff  30697 Apr 19 21:44 editor_2017.2.1f1_raw.log
-rw-r--r--  1 lacostej  staff  29974 Apr 19 21:44 editor_2017.2.1f1_u3d_arg.log
-rw-r--r--  1 lacostej  staff  111894 Apr 19 21:45 editor_2017.3.0f2_arg.log
-rw-r--r--  1 lacostej  staff     823 Apr 19 21:45 editor_2017.3.0f2_err.log
-rw-r--r--  1 lacostej  staff   32451 Apr 19 21:45 editor_2017.3.0f2_raw.log
-rw-r--r--  1 lacostej  staff   31728 Apr 19 21:45 editor_2017.3.0f2_u3d_arg.log

I asked Unity to clarify if this was intended behavior. I'll wait for their answer if any.

On our side: