SDK 1.9 example plugin fail, OSX, need some help...

[RootlessAgrarian]

After the good news that SDK 1.9 is (supposed to be) OSX compatible, I had a whack at testing one of the example plugins (telemetry_position.so). It didn't work. It fails so silently that I'm not sure how to proceed. (I posted this question to github also. Am x-posting this here because the github thread is old and quiet.) Here's the story so far:

I did manage to compile the example telemetry_position.so (this is what I am mostly interested in). I then tracked down the game binary and created a plugins dir in the same dir, which under OSX is a mouthful:

Code: Select all

/Volumes/DATA/Users/MY_USERNAME/Library/Application\ Support/Steam/steamapps/common/Euro\ Truck\ Simulator\ 2/Euro\ Truck Simulator\ 2.app/Contents/MacOS

I started the game. I got a warning popup saying that I'm attempting to invoke advanced SDK features, which seemed like a good sign. Also, in the game log, I saw an ack that the .so has been loaded (or at least an attempt has been made to load it):

Code: Select all

00:00:04.002 : loading 'telemetry_position' '/Volumes/DATA/Users/de/Library/Application Support/Steam/steamapps/common/Euro Truck Simulator 2/Euro Truck Simulator 2.app/Contents/MacOS/plugins/telemetry_position.so'

I get no error messages from this load. However, I also get no telemetry log file after quitting the game. I do get an unload confirmation message during the shutdown:

Code: Select all

00:12:47.086 : unloaded 'telemetry_position'

I thought perhaps the opened file was not being closed properly at exit, so I took out the "ifdef linux" near the end of the telemetry_position.cpp source, which I thought might enable finish_log properly for the OSX environment; so I hope the log file is being closed after writing. However I have also loaded the plugin and driven the truck around a bit, then left the truck parked and looked for the telemetry log file with the game still open: no sign of it. I don't think the file is ever being opened.

The .so opens its log file with a simple

Code: Select all

log_file = fopen("telemetry_position.log", "wt");

which doesn't give much of a clue as to where this file will be created. Rather than have to rummage, I tried editing this fopen command to specify the file name as

Code: Select all

/tmp/telemetry_position.log

but still I got no telem log file in /tmp after starting and then exiting the game. Or while running.

Even if no position logging is done, the .so should write one line to the log file immediately after opening it:

Code: Select all

fprintf(log_file, "Log opened\n");

So I was expecting to find at least a stub output file with this one line in it. It's discouraging to get such a silent failure; seems to augur badly for debugging, 'cos if I can't write debug msgs to a log file ... you see the problem... I'm beginning to think that the init function for the plugin is never getting called but I have no idea how to determine this or how to fix it if so. If I knew the function call to write to the devcon, then I might be able to do some debug using the

Code: Select all

sdk reinit

command (which I've tried btw -- didn't seem to do anything, just executed with no error, silence). But I have no idea what the syntax is for writing to dev con from ets2 cpp source. If anyone has example code for this I'd sure like to see it!

So right now I have a .so that loads -- apparently w/o error -- but does nothing, with no error message or any indication of what has failed or how. help...?

[Komat]

The init function should be called shortly after confirming that advanced features message. Maybe there is some error message in the log from around that moment.

[RootlessAgrarian]

Hi Komat, thanks for responding. Here's a typical log file...

https://zerobin.net/?705e322220a68699#F ... wrU/4eQGc=

I have scrolled through it a few times w/o finding any suggestive errors. Can't find the strings sdk/SDK anywhere, occurrences of "init" are harmless, etc.

Could you tell me if there is a function call that lets me write messages to the dev con? If I can do that, I might be able to tell whether the init routine is ever getting called. I assume it is supposed to be called automagically on startup -- I don't have to set some g_option or type in a console command to start the plugin?

one thing I noticed today is

Code: Select all

00:00:08.650 : loading 'telemetry_position' '/Volumes/DATA/Users/de/Library/Application Support/Steam/steamapps/common/Euro Truck Simulator 2/Euro Truck Simulator 2.app/Contents/MacOS/plugins/telemetry_position.so'
00:00:11.629 : uset s_sfx_enabled "1"

there seems to be a bit of a delay between .so loading and the next event in the log -- is that 3 seconds? almost as if something were timing out waiting for a resource, then dying silently... but I am speculating in the dark here.

Also I should add, my OSX platform is running El Cap 10.11.6, a pretty stable release. Does OSX compatibility in the SDK rely on some arcane OSX feature that was only added as of Sierra? or should it work on El Cap? I have a spare machine I can upgrade to Sierra if it's worth trying that experiment.

[Komat]

Could you tell me if there is a function call that lets me write messages to the dev con? If I can do that, I might be able to tell whether the init routine is ever getting called.

There is one. If you check beginning of scs_telemetry_init, it calls it if the init_log() call fails. Also you can put there some code which would cause the process to exit or crash when run so you will notice that it was executed.

I assume it is supposed to be called automagically on startup -- I don't have to set some g_option or type in a console command to start the plugin?

Yes, it is called after you confirm the message box.

there seems to be a bit of a delay between .so loading and the next event in the log -- is that 3 seconds?

That next event happens when you start loading profile so the gap is you confirming the message box and selecting profile.

Does OSX compatibility in the SDK rely on some arcane OSX feature that was only added as of Sierra? or should it work on El Cap?

There is nothing special in it. It is basically normal Unix dlopen. It is the same code which we are using on Linux (the linux uses additional RTLD_DEEPBIND flag however that is the only difference). There should be a error message if the open fails or if it is unable to find the functions. In which case you would not receive the UI message.

[RootlessAgrarian]

Hi Komat thanks for tip, I have just instrumented the .so and according to the output on devcon it is doing exactly what it should including writing to the telem log file! Here is a log excerpt (sorry about the ERROR text, I have just been copy/pasting existing lines of code. Aside from _error and _warning is there a harmless flavour? _info maybe? haven't found any other msg types in the sdk source yet.)

Code: Select all

00:21:25.317 : loading 'telemetry_position' '/Volumes/DATA/Users/de/Library/Application Support/Steam/steamapps/common/Euro Truck Simulator 2/Euro Truck Simulator 2.app/Contents/MacOS/plugins/telemetry_position.so'
00:21:25.317 : <ERROR> SDK About to init telemetry log file
00:21:25.317 : <ERROR> SDK entering init_log
00:21:25.317 : <ERROR> SDK init_log calling fopen /tmp/telemetry_position.log wt
00:21:25.319 : <ERROR> SDK init_log opened log file
00:21:25.319 : <ERROR> SDK Initialised telemetry log file
00:21:25.319 : <ERROR> SDK log_line writing to telem log file
00:21:25.319 : <ERROR> SDK called log_line to write game version, now check version
00:21:25.319 : <ERROR> SDK Done with channel registry
00:21:25.319 : <ERROR> SDK calling memset sizeof(telemetry)
00:21:25.319 : <ERROR> SDK finished init
00:21:25.319 : <ERROR> SDK log_line writing to telem log file
00:21:25.335 : <ERROR> SDK log_line writing to telem log file
00:21:25.351 : <ERROR> SDK log_line writing to telem log file
00:21:25.367 : <ERROR> SDK log_line writing to telem log file

The plugin thinks it is working just fine. Not only that, I now see a telemetry_position.log file in /tmp! So... I have a bad feeling that just adding the debug lines changed the behaviour... weird. Gonna revert to the vanilla code later today & try it again.

One more question: how can I include the typical ETS2 time stamp (eg 00:21:25.319) in a print stmt? how do I access that (global?) variable?

(update) yup I think there might be a subtle mem management problem in the .so code.

I started pruning the debug output; first I commented out just one of my debug lines (a potentially noisy one,

Code: Select all

//      game_log (SCS_LOG_TYPE_error,"SDK log_print writing to telem log file");

In practise it doesn't seem to get called, but I thought I'd silence it anyway. When I did an sdk reload with the other noisy line (log_line writing to telem log file) still enabled, ETS2 segv'd.

Code: Select all

Path:                  /Volumes/VOLUME/*/Euro Truck Simulator 2.app/Contents/MacOS/eurotrucks2
Identifier:            com.scssoft.ets2
Version:               1.22.2 (67890)
Code Type:             X86-64 (Native)
Parent Process:        ??? [1]
Responsible:           eurotrucks2 [26143]
User ID:               501

Date/Time:             2017-09-20 11:45:01.925 -0700
OS Version:            Mac OS X 10.11.6 (15G1217)
Report Version:        11
Anonymous UUID:        CEB10642-8A58-44B4-E9E1-9531A7F376FD


Time Awake Since Boot: 130000 seconds

System Integrity Protection: disabled

Crashed Thread:        0  MainThrd  Dispatch queue: com.apple.main-thread

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       KERN_INVALID_ADDRESS at 0x0000000000000000
Exception Note:        EXC_CORPSE_NOTIFY

VM Regions Near 0:
--> 
    __TEXT                 0000000101039000-0000000102125000 [ 16.9M] r-x/rwx SM=COW  /Volumes/VOLUME/*/Euro Truck Simulator 2.app/Contents/MacOS/eurotrucks2

Thread 0 Crashed:: MainThrd  Dispatch queue: com.apple.main-thread
0   ???                           	000000000000000000 0 + 0
1   telemetry_position.so         	0x00000001826fd8ed finish_log() + 45
2   telemetry_position.so         	0x00000001826fe974 scs_telemetry_shutdown + 20
3   com.scssoft.ets2              	0x0000000101ca51f1 0x101039000 + 13025777
4   com.scssoft.ets2              	0x0000000101ca49b8 0x101039000 + 13023672
5   com.scssoft.ets2              	0x0000000101117e14 0x101039000 + 912916
6   com.scssoft.ets2              	0x0000000101af58cc 0x101039000 + 11258060
7   com.scssoft.ets2              	0x0000000101af5ea3 0x101039000 + 11259555
8   com.scssoft.ets2              	0x00000001011293ba 0x101039000 + 983994
9   com.scssoft.ets2              	0x000000010177816e 0x101039000 + 7598446
10  com.scssoft.ets2              	0x0000000101b00a45 0x101039000 + 11303493
11  com.scssoft.ets2              	0x0000000101af5195 0x101039000 + 11256213
12  com.scssoft.ets2              	0x000000010103a9b3 0x101039000 + 6579
13  libdyld.dylib                 	0x00007fff8fba45ad start + 1

I then commented out the other noisy line

Code: Select all

//      game_log (SCS_LOG_TYPE_error,"SDK log_line writing to telem log file");

restarted ETS2, and now no problem, ETS2 running normally and telem fp still being written.

So my conclusion is that this code is in some way fragile, not sure how, but it seems like it should not (a) start working when N log print lines are added, (b) segv when one line (which didn't seem to get called at runtime) gets commented out, then (c) stop segv'ing when another line (which was called and worked at runtime) gets commented out. Meanwhile it's working well enough for now (though I wonder what memory is getting tromped on invisibly, yikes!) and I can have a whack at building my plugin. I'm kind of short of hacking time right now but will revert to vanilla (fresh unpack of the zip file) this evening and start from scratch, see if I can replicate the original failure. If there is memory mangling going on then of course failure could well be very silent (until there's an accvio!).

If there is anything I can do to help you find the segv problem let me know...

[RootlessAgrarian]

Puzzled... I just reverted to the vanilla 1.9 release of the SDK, recompiled, reloaded (this made ETS2 segv, which seems to have something to do with unloading previous version). Restarted game, loaded the .so at startup, and... yippee a telemetry log is being written. Not in the usual directory where game_log.txt and other files are written, but at an odd position in the dir hierarchy for the game binary (in the app Contents dir, which in OSX land also contains Frameworks, PkgInfo, MacOS, etc). Yesterday I swear I did a find . -name '*telem*.*' -print on that whole dir tree and there was no log file, so....?

Just for grins I tried changing the log file location to /tmp as before, and sure enough it now writes a file in /tmp. So the failure I saw yesterday is not reproducible today. [Scratches head] Could I have broken it by including the ifdef linux code at end of file when compiling for OSX? that's one possibility. I guess I will just be happy that it works for now; but I don't have a real solid confident feeling about this SDK yet (at least not under OSX). I'll be playing with it for quite a while over the next month or two (trying to set up a UDP service offering the info to local clients) so if it's fragile it should break again pretty soon. Whereas if it was I who broke it in my attempts to find the mysterious log file, then that shouldn't happen again.

Thanks again Komat

[Komat]

how can I include the typical ETS2 time stamp (eg 00:21:25.319) in a print stmt? how do I access that (global?) variable?

That is generated by the game logging system. The plugins do not have acccess to this value.

If there is anything I can do to help you find the segv problem let me know...

The game_log variable is cleared from scs_telemetry_shutdown before calling finish_log so if you tried to print something from the finish_log, that would cause the crash.

Could I have broken it by including the ifdef linux code at end of file when compiling for OSX? that's one possibility. I

That should only apply when the library is finally unloaded. It is only meant to flush the file in case scs_telemetry_shutdown was not called for some reason (e.g. game exits itself because of a critical error) and should not affect the normal operation.