gamemode icon indicating copy to clipboard operation
gamemode copied to clipboard

logging control

Open axet opened this issue 2 years ago • 15 comments

Is your feature request related to a problem? Please describe.

log spamming when running the game (also no error message).

gamemodeauto: 
gamemodeauto: 
gamemodeauto: 
gamemodeauto: 
gamemodeauto: 
gamemodeauto: 

Describe the solution you'd like

having GAMEMODE_LOG=none env variable

Describe alternatives you've considered

none

Additional context

most wine wrappers / libs has option to disable logging for example:

      export WINEDEBUG=-all,$WINEDEBUG
      export DXVK_LOG_LEVEL=none
      export VKD3D_DEBUG=none
      export MANGOHUD_LOG_LEVEL=off

Currently gamemode spamming using stderr channel:

fprintf(stderr, "gamemodeauto: %s\n", gamemode_error_string());

axet avatar Jun 17 '23 07:06 axet

Looking at the code this logging is only called when there is a problem so the bug looks to be more that gamemode_error_string() returns nothing on what the error is than that the logging is there in the first place. This logging is done in 4 places in lib/gamemode_client.h so my initial idea would have been to add a number to each one to at least determine which one of them that is failing for you to have a start of finding out why you get no error string.

HenrikHolst avatar Jun 24 '23 21:06 HenrikHolst

Booth 'REAL_internal_gamemode_request_start' and 'REAL_internal_gamemode_request_end' are failing.

axet avatar Jun 25 '23 06:06 axet

That part of the code:

	if (res == -1 && dbus_error_is_set(&err))
		log_error("D-Bus error: %s", err.message);

Simplifying the check, showing error d-bus error with no text message

	if (res == -1)
		log_error("D-Bus error: %s", err.message);

axet avatar Jun 25 '23 06:06 axet

I wonder if this is possible connected to #426 since this is related to dbus errors and inhibiting the screen lock is done via dbus aswell.

HenrikHolst avatar Jun 25 '23 17:06 HenrikHolst

dbus_error_is_set

well this atleast means that make_request() failed but that err wasn't set (aka no D-BUS error)

HenrikHolst avatar Jun 25 '23 17:06 HenrikHolst

so it should be this code in make_request() (client_impl.c)

	dbus_error_init(&err);
	res = -1;
	if (dbus_set_error_from_message(&err, msg)) {
		dbus_set_error(error,
		               err.name,
		               "Could not call method '%s' on '%s': %s",
		               method,
		               dest,
		               err.message);
	} else if (!dbus_message_iter_init(msg, &iter) ||
	           dbus_message_iter_get_arg_type(&iter) != DBUS_TYPE_INT32) {
		dbus_set_error(error, DBUS_ERROR_INVALID_SIGNATURE, "Failed to parse response");
	} else {
		dbus_message_iter_get_basic(&iter, &res);
	}

	/* free the local error */
	if (dbus_error_is_set(&err))
		dbus_error_free(&err);

	return res;

The first if sets error so it isn't that one, so its either the else if or the call to dbus_message_iter_get_basic() that fails leaving res at -1 but setting no error to the error variable.

HenrikHolst avatar Jun 25 '23 18:06 HenrikHolst

Same. No error message and -1 as res.

axet avatar Jun 25 '23 18:06 axet

Not sure what you mean by same? I listed the code as it is, so no change. What I would do is try to add some logging inside that if else-if else to see why ret is still -1

HenrikHolst avatar Jun 25 '23 18:06 HenrikHolst

No. I just applied the code you posted. I did not check if it is a same code :)

axet avatar Jun 25 '23 18:06 axet

hehe :)

HenrikHolst avatar Jun 25 '23 18:06 HenrikHolst

This is my full log of running wine app under gamemode. Notice different amount of "start" (22) and "stop" (14) commands. Some "start" commands were successful. D-bus error line only appears when ret == -1

d3 -l
wine folder found: /media/axet/128GB/Games/Diablo III
winearch set to win64
working directory: /media/axet/128GB/Games/Diablo III/D3
gamemodeauto3: start 
gamemodeauto3: start 
GameMode ERROR: D-Bus error: (null)
gamemodeauto3: D-Bus error: (null)
gamemodeauto3: start 
GameMode ERROR: D-Bus error: (null)
gamemodeauto3: D-Bus error: (null)
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto5: stop 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto5: stop 
gamemodeauto3: start 
gamemodeauto5: stop 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto5: stop 
gamemodeauto3: start 
gamemodeauto3: start 
gamemodeauto5: stop 
gamemodeauto3: start 
gamemodeauto5: stop 
gamemodeauto5: stop D-Bus error: (null)
gamemodeauto5: stop 
gamemodeauto5: stop 
gamemodeauto5: stop 
gamemodeauto5: stop 
gamemodeauto5: stop 
gamemodeauto5: stop 
gamemodeauto5: stop 
GameMode ERROR: D-Bus error: (null)
gamemodeauto5: D-Bus error: (null)

axet avatar Jun 27 '23 05:06 axet

Now I'm not 100% clear with the inner workings of gamemode but I find it strange that gamemodeauto is even a thing here, AFAIK that is some lib that is used in LD_PRELOAD to force in gamemode instead of running it under gamemoderun (but I can be mistaken).

Does the same problems happen if you just run the "gamemode-simulate-game" binary?

HenrikHolst avatar Jun 27 '23 22:06 HenrikHolst

gamemode-simulate-game works fine. no errors reported.

axet avatar Jun 28 '23 05:06 axet

ok looks like I am extremely thick... gamemoderun is just a script that uses LD_PRELOAD so ofc you would trigger the auto-stuff there, meanwhile the gamemode-simulate-game is just the main.c from examples/ so it does a "proper" connect to gamemoded via d-bus.

so there is for some reason a difference on your system if things are launched via the d-bus api directly or by injecting libgamemodeauto.so into the running application.

HenrikHolst avatar Jun 28 '23 22:06 HenrikHolst

Maybe due to different ABI? x32 / x64? I'm using wine64, but who knows...

axet avatar Jun 29 '23 03:06 axet