The nexe loading log could be more useful

[illwieckz]

Here is what I get when I try to load an exe on arm:

$ ./daemonded -set vm.sgame.type 1 +devmap plat23
Using loader args:  nacl_helper_bootstrap nacl_loader --r_debug=0xXXXXXXXXXXXXXXXX --reserved_at_zero=0xXXXXXXXXXXXXXXXX -v -B irt_core-arm.nexe -e -i 100:25 -- sgame-arm.nexe 100 
Warn: IPC: Socket closed by remote end

The message is meaningless.

If I run the command by hand, this is what I get:

$ ./nacl_helper_bootstrap nacl_loader --r_debug=0xXXXXXXXXXXXXXXXX --reserved_at_zero=0xXXXXXXXXXXXXXXXX -v -B irt_core-arm.nexe -e -i 100:25 -- sgame-arm.nexe 100
sel_ldr argument list:
nacl_loader --r_debug=0x0000000040002000 --reserved_at_zero=0x0000000040002000 -v -B irt_core-arm.nexe -e -i 100:25 -- sgame-arm.nexe 100
[471888,4149006400:03:28:04.970230] Error while loading "sgame-arm.nexe": CPU model is not supported
[471888,4149006400:03:28:04.971045] NaClPerfCounterInterval(SelMain __start__:SnapshotBlob): 1153 microsecs
[471888,4149006400:03:28:04.971180] NACL: Application output follows
[471888,4149006400:03:28:04.971212] NaClAppStartModule: module not loaded
Dumping vmmap.
In PrintVmmap
Done.

This is far more useful.

[slipher]

I guess it must be some kind of flushing problem. Either the process exits without flushing or we kill it before it can write and flush its output.

[slipher]

Wait a minute, did you actually open the log file? You just show the daemonded output in the OP but you're supposed to look in <homepath>/cgame.nacl_loader.log to see this stuff.

[DolceTriade]

I think we want to put this not in the cgame.nacl_loader.log since I don't think this is enabled by default and print these types of errors to the console because that's where people look for errors?

[slipher]

I think we want to put this not in the cgame.nacl_loader.log since I don't think this is enabled by default and print these types of errors to the console because that's where people look for errors?

No, because that would be too much spam. On my machine it prints 17 lines for a normal startup at the default (lowest other than muted) log level.

[DolceTriade]

It obviously doesn't always have to print to console, but maybe in the error case it can. This means that we have to always log to file and maybe read it back (or the last 10 lines) or something in the event of an error.

[illwieckz]

Wait a minute, did you actually open the log file? You just show the daemonded output in the OP but you're supposed to look in <homepath>/cgame.nacl_loader.log to see this stuff.

I didn't knew this file exists, I never used it and I never seen someone using it to troubleshoot IPC: Socket closed by remote end errors. I always helped people reporting IPC: Socket closed by remote end errors by blindly iterating some checklist (like verifying if NX bit is enabled in BIOS) without reading this file at all.

When such error happens there is even no message saying there is more information to be found in that file.

Can we dump this log file content in case of error?

[slipher]

I have asked people to send me the loader log to debug stuff, but the truth is it has rarely been useful. For example with the Slackware bug where the kernel configuration setting blocked the executable from loading at a low address, the process never even started so it couldn't log anything.

[illwieckz]

Well, even with my current case the log doesn't help me that much, but I'm just super-surprised we have more logs.

At least for me Error while loading "sgame-arm.nexe": CPU model is not supported confirms me it actually tries to load the right file and that it may be failing at detecting something about the CPU.

[slipher]

Is there anything more we could ask of this log?