Feature - Implemented Relogging to improve ping

I have no explanation for why api.php is not slower for you on a connection where council.php is slower.
Not sure what it is, but api.php just seems to be consistent for me between each one. Tried again using 100 attempts instead and between two different logins.

First login:
council.php:
> ash ping(100, "council.php")

Preference pingLatest changed from council.php:10:167:199:1849:26820:184 to council.php:100:159:452:20596:266880:205
Returned: record {string page; int count; int low; int high; int total; int bytes; int average; int bps;}
page => council.php
count => 100
low => 159
high => 452
total => 20596
bytes => 266880
average => 205
bps => 12957
api.php:
> ash ping(100, "api.php")

Preference pingLatest changed from council.php:100:159:452:20596:266880:205 to api.php:100:79:96:8179:196200:81
Returned: record {string page; int count; int low; int high; int total; int bytes; int average; int bps;}
page => api.php
count => 100
low => 79
high => 96
total => 8179
bytes => 196200
average => 81
bps => 23988
After relogin command:
council.php:
> ash ping(100, "council.php")

Preference pingLatest changed from api.php:10:78:80:787:19620:78 to council.php:100:115:208:12909:267360:129
Returned: record {string page; int count; int low; int high; int total; int bytes; int average; int bps;}
page => council.php
count => 100
low => 115
high => 208
total => 12909
bytes => 267360
average => 129
bps => 20711
api.php:
> ash ping(100, "api.php")

Preference pingLatest changed from council.php:100:115:208:12909:267360:129 to api.php:100:78:86:8020:196200:80
Returned: record {string page; int count; int low; int high; int total; int bytes; int average; int bps;}
page => api.php
count => 100
low => 78
high => 86
total => 8020
bytes => 196200
average => 80
bps => 24463


So after the relogin, my council.php pings were significantly better, but api.php was essentially the same
 

fronobulax

Developer
Staff member
OK, I now understand how stealth login used to work.

1) If you login without /q, your contacts will be alerted. When you log out, they will be alerted again.
2) If you login with /q, your contacts will not be alerted. When you log out, they will still not be alerted.
3) As coded, KoLmafia stripped off and ignored whether or not you actually typed /q; the ONLY thing that affected whether it was added to your username when requesting login.php was the preference checkbox on the Login Frame.
4) That includes logging in via the cli with the “login” command. You started up with -CLI and typed “login name/q” and thought that was a stealth login? Unless the checkbox on the Login Frame was checked, nope. You typed “login name” and thought that was NOT a stealth login? If the checkbox was checked last time you were on the Login Frame, too bad. Stealthy you are.

In any case, points 1 and 2 mean it is useless to try to make time-ins stealthy, whether or not your initial login was not stealthy; your contacts will be alerted the first time you log out and will not be alerted for any subsequent login/logout in the session.

I’m inclined to just give up on trying to rationalize that. Your contacts will just have to see a flurry of login/logout/login messages as you try for a better connection.

Login Frame only.
Check box unchecked.
Case 1) above.

For me this is a change in behavior due to your change. If I care it is because the most recent message tells me a character has logged out when indeed they are currently logged in. I can live with that if you choose not to deal with fixing it. I report it because your preference is to be deliberate when you introduce changes in behavior.

If every login/out respected the /q then I would have a screenful of messages and decide the clutter was too much and set the preference to stealth.

Perhaps a user desire not to be stealthy disables the automated retry?

Regardless "will not 'fix'" is an acceptable response.
 

MCroft

Developer
Staff member
It has a harmless flaw during rollover of trying and returning a 0 second ping.

But it might put bad values in certain places, so it might be better to abort if we get a rollover message.
Java:
> ping 10 api verbose


Ping #1 of 10...
-> 0 msec (0 bytes)
Ping #2 of 10...
-> 0 msec (0 bytes)
Ping #3 of 10...
-> 0 msec (0 bytes)
Ping #4 of 10...
-> 0 msec (0 bytes)
Ping #5 of 10...
-> 0 msec (0 bytes)
Ping #6 of 10...
-> 0 msec (0 bytes)
Ping #7 of 10...
-> 0 msec (0 bytes)
Ping #8 of 10...
-> 0 msec (0 bytes)
Ping #9 of 10...
-> 0 msec (0 bytes)
Ping #10 of 10...
-> 0 msec (0 bytes)
10 pings to api.php at 0-0 msec apiece (total = 0, average = 0) = 0 bytes/second
 

Irrat

Member
Not sure what it is, but api.php just seems to be consistent for me between each one. Tried again using 100 attempts instead and between two different logins.

First login:
council.php:

api.php:

After relogin command:
council.php:

api.php:



So after the relogin, my council.php pings were significantly better, but api.php was essentially the same

I think you had a bad test.

js const funt = (url) => {const started = Date.now(); for (let i = 0; i < 5; i++) { visitUrl(url); } print( Date.now() - started);}; funt("council.php");funt("api.php?what=events&for=Antilag_by_Irrat");

You were calling api.php without any params, so it would exit faster is my impression.
I managed to hit a bad server and had both numbers increase as expected. But when removing the params from api.php, I've noticed it is a lot quicker.

Aka, it takes less work for the server to give us a reply, which isn't what we want. Since we want to measure the workload.
 

Veracity

Developer
Staff member
I think you had a bad test.
That's a little strong. :) I may or may not agree, but let's see.

js const funt = (url) => {const started = Date.now(); for (let i = 0; i < 5; i++) { visitUrl(url); } print( Date.now() - started);}; funt("council.php");funt("api.php?what=events&for=Antilag_by_Irrat");

You were calling api.php without any params, so it would exit faster is my impression.
Your impression is correct, and is a good point.
api.php with no parameters gives boilerplate response telling you how to use the call.
It doesn't actually hit up any user data.

I added this to PingRequest:

Code:
  private void addFormFields() {
    switch (this.pingURL) {
      case "api.php" -> {
        this.addFormField("what", "status");
        this.addFormField("for", "KoLmafia");
      }
    }
  }
And instead of taking from 20-40 msec per test, it's taking 36-65.
My login "goal" would need to be 40, rather than 30.

The advantage of "status" is that it hits up a lot of KoL user data - and is constant, while you are idle (although you need not be idle while executing it; ping() measures the elapsed time of each request separately, rather than the duration of the whole test, from beginning to end).

I changed "status" to "events" and I'm getting from 27-54 msec per test. That's looking at user state, but is NOT constant, since events can come in at any time. With no events, the data per ping is 2 bytes...

I managed to hit a bad server and had both numbers increase as expected. But when removing the params from api.php, I've noticed it is a lot quicker.

Aka, it takes less work for the server to give us a reply, which isn't what we want. Since we want to measure the workload.
I don't think I agree with that.

Consider what we are testing.

KoL has a number of servers on AWS.
They may or may not all be the same type.
They may be in a single region, or they may be spread across several regions.

What do we test?

1. On your computer
KoLmafia makes a request to KoL.
2. In the network
It travels from your computer to an AWS server (at the whim of Internet routers.)
It is handed off to a specific server associated with your session.
3. On KoL's server
The server hands it off to a process/thread to handle your session.
That does some amount of setup to connect to your user/session.
It handles the request and sends the reply.
4. In the network
The reply makes its way back to your computer.
5. On your computer
It is given to KoLmafia, which, itself handles the reply.

We measure the duration of that whole sequence, sans KoLmafia's processing time for the response.
(That's why PingRequest bypasses that; if you use council.php, we do not parse the council text.)
(That is also why the "ping" command and function measures the elapsed time of each request and totals them, rather than including script execution and such.)

We are interested in 2-4, but 2 and 4 are not KoL's fault, as such.
Only 3 is the result of load on KoL's server.
Only 3 is "the workload".

Yes, we want to measure "the workload". Where you and I may disagree is that I think any "constant" task on KoL's server is fine; much of the variation will result from task scheduling in competition with other user tasks. If you have to look up user state, perhaps database contention. If you have to change user state, even more of that.

I do literally all of my ascension in the Relay Browser. Only in aftercore do I automate turns. And the server differences are very noticeable when, for example, I stasis a combat and the combat rounds just scroll on by in the gCLI as opposed to having a second or more between each round. And I observe that if api.php (no arguments) is <= 30 msec, rounds flow on by speedily.

Would it be more accurate to use api.php?what=status and use a goal of <= 40? For me? Probably not. For other people who, for some reason, "don't see api.php times increasing" as the server is more loaded? Perhaps.

I'm going to add two more options for ping testing: the page to use and the number of iterations.
You want ping() - as executed at login - to hit council.php 5 times? Go for it.

I'm not sold on api.php?what-status, since I see measurable difference even without the arguments. To my eye, all the arguments do is slow down the tests. I will experiment more.
 

MCroft

Developer
Staff member
Would it be worthwhile to just calculate a start time - stop time value on every request and put it in the response object? We don’t have to expose it, but when we want it, it might be useful to the dev team.
 

Irrat

Member
Am I missing some conversation?

When I run "relog" it will log me out, then log me in. Which sounds fine, except I'm not sure why we're bothering to log out.
Its always been my impression that you can log in without logging out. Which sounds weird if taken out of context tbh.

So I commented out the logout call and ran it. I'm still being relogged and its still switching servers. I just don't need to send a logout. It just starts with a login request.

The only downside is that mafia has some minor cleanup done for logouts; however that's easy to shift around.

That said, I have noticed that sometimes chat is attempting to fetch messages while I'm in an invalid state. Seems minor, I think there's already a helper method to see if we're in the middle of relogging.

I'm also curious if we can skip the "lchat.php" fetching for the password hash, given it's calling api.php?status which provides the hash. PasswordHashRequest
 

Veracity

Developer
Staff member
All “conversation” that I have seen is on this thread or in PR comments.

If you can go straight to login.php while already logged in and KoL will reassign your server, that is news to me! Exciting news.

lchat to get the password hash is from the very beginning days of Kolmafia - at least 5 years before api.php existed. Don’t forget that api.php redirects to afterlife.php if you are in Vslhalla.

I am certainly open to shifting around what happens in login/timein/logout.

And yes - chat’s interaction with login state has not kept up with modern technology, either.

This is exciting. My latest PR finishes up the properties and the GUI interface in Preferences/General/Connection Options, allowing you to fo ping tests and timeins right from there, which will make experimentation trivial.
 

Veracity

Developer
Staff member
Wow. I commented out all the calls to logout.php before timing in, and it sure does look like I get a new server each time.

Code:
> timein

Sending login request...
Ping test: average delay is 65 msecs.
Loading character status...
Requests complete.

> ping 100

100 pings to api.php at 34-98 msec apiece (total = 5542, average = 55) = 35402 bytes/second

> ping 100

100 pings to api.php at 33-98 msec apiece (total = 5540, average = 55) = 35415 bytes/second

> timein

Sending login request...
Ping test: average delay is 28 msecs.
Loading character status...
Requests complete.

> ping 100

100 pings to api.php at 25-38 msec apiece (total = 2843, average = 28) = 69011 bytes/second

> ping 100

100 pings to api.php at 24-37 msec apiece (total = 2827, average = 28) = 69402 bytes/second

Thanks for telling me about this!
 

Veracity

Developer
Staff member
If every login/out respected the /q then I would have a screenful of messages and decide the clutter was too much and set the preference to stealth.
Revision r27466 (which you just approved) no longer issues a logout when timing in.

I just did some experiments.

My main is on the contact list of a multi.

I log in without /q, the multi sees "Veracity logged on" as an event.
If I "timeout", it submits a logout request and I see "Veracity logged off".
If I log out, I do NOT see "Veracity logged off".
I do not understand that.

With the current code which issues timein logins with /q, whether or not you initially logged in that way, I can time in as often as I want and I never see another "Veracity logged in".

Commenting out the line which makes timeins have /q, every time I log in, I see another "Veracity logged in".

So, I think the strategy of re-logging in with /q, always, is sound.

I am planning on making a fix, anyway: if you use "login name/q", then you get a stealth login, regardless of whether "stealthLogin" is true. For some reason, we were ignoring that - and that was not my change.
 

Veracity

Developer
Staff member
If we do not make timeins stealthy:

User logs in without /q
- Every timein says "User logged on"
+ When you log off, it reports "User logged off"

If we make timeins stealthy:

User logs in without /q
+ Timeins do not report "User logged on"
- If you did timein at least once, when you log off it does NOT report "User logged off".

What happens when KoL itself times you out? It effectively logs you off. Does it report that to your contacts?
 

fronobulax

Developer
Staff member
<veer>I built and ran with 27465 today. My first login attempt gave me times over 300 where I have been used to seeing under 30. I kept trying and getting the high numbers. I cleared the stats for reasons that are obscure in hindsight. I then discovered that I was using a VPN and that my traffic was going through the Netherlands. I straightened all that out, cleared stats and then no one tried multiple logins. They got an acceptable time on the first try. I also noticed the absence of any messages to other characters about logging in and out. What this means is I am unlikely to be able to easily reproduce previous conditions. :) </veer>
 

Irrat

Member
<veer>I built and ran with 27465 today. My first login attempt gave me times over 300 where I have been used to seeing under 30. I kept trying and getting the high numbers. I cleared the stats for reasons that are obscure in hindsight. I then discovered that I was using a VPN and that my traffic was going through the Netherlands. I straightened all that out, cleared stats and then no one tried multiple logins. They got an acceptable time on the first try. I also noticed the absence of any messages to other characters about logging in and out. What this means is I am unlikely to be able to easily reproduce previous conditions. :) </veer>
You mean no one 1 right? 😉
 

Veracity

Developer
Staff member
Clearing the stats is the correct reaction if you change computer or network (which is what you did by connecting through a VPN) and specify a “threshold”, which is a percentage above your lowest observed time.

As long as your “failed ping test” behaviour is “login” - i.e. accept what you end up with - you were not blocked from logging in; you just spent extra time discovering that your gaming experience will be undesirable.
 

fronobulax

Developer
Staff member
27467

Every character rejected the first connection and retried. There were no character logged out messages and the logged in messages were exactly as I remembered them as being before the ping test. Between the new code and the resets it looks like there is no longer an issue with not using Stealth Login. Thank you.
 

Veracity

Developer
Staff member
There are two ways it could work if you login without /q and there are retrys:

If timing in uses /q:

(You log in)
(KoL remembers you are not in stealth mode)
Character logged in.
(We timein with /q)
(KoL remembers you are in stealth mode)
(No Character logged in messsge)
(Eventually you log out)
(No Character logged out message)

If timing in does not use /q:

(You log in)
(KoL remembers you are not in stealth mode)
Character logged in.
(We timein without /q)
(KoL remembers you are not in stealth mode)
Character logged in.
(Eventually you log out)
(KoL remembers you are not in stealth mode)
Character logged out.

There is no other way timing in can behave.
I’m going to make it s preference.
 

AlbinoRhino

Active member

r27468

So I got this on login for pingShortest: api:20:0:0:0:0:0. I am also getting it with "Time In" button & "relog" command.
And since mafia believes it is getting a 0 ms response, "Time In" button in prefs, and cli "relog" command only try once when used...pingLoginGoal is 38 ms.
I am attaching a debug log of using the "Time In" button in preferences but I'm not sure what log you may need. If you need something else I would be happy to collect it!
 

Attachments

  • DEBUG_20230712.txt
    60.3 KB · Views: 1

Veracity

Developer
Staff member
Interesting:

Code:
Retrieved: https://www.kingdomofloathing.com/login.php
...
Ping test: average delay is 0 msecs.
It didn't actually run a test.

I bet you had pingDefaultTestPage as "api.php" and we didn't normalize it to "api".
(Testing. Yes, that would do it.)

Go to Preferences/General/Connection Options.
On "KoL page to ping" click on (events) and then back to api.

That will fix it for you.

I have a one-line fix coming, by and by, which will obviate that: api.php will be normalized to api before running a default ping test.
 

Veracity

Developer
Staff member
I guess this means it is time to announce today's changes:

Revision r27470:
  1. Fixed login command to allow /q
    Finds saved password for name without /q
    LoginRequest obeys /q
  2. Preference pingStealthyTimein (boolean) specifies whether logging in with same request (e.g. timing in) uses /q
    (Stealth mode checkbox - stealthLogin - still works)
    You can manipulate this property in Connection Options in either LoginFrame or Preferences/General
  3. When redirect, store base URL only as page;
    afterlife.php?realworld-1 -> afterlife.php
  4. Changed saved ping page to be "api", "council", or "main". I.e., without the .php
    I attempted backwards compatibility with historical properties which have the page listed with .php; strip it off when read property, omit it when write property.
    Add (events) and (status) as available ping pages.
    api.php?what=events&for=KoLmafia
    api.php?what=status&for=KoLmafia
    In the "ping" command, page keywords are api, events, status, council, and main
    Irrat's script does the equivalent of "ping 5 events"
  5. When a ping is redirected, redirect to the full URL, but save the page as just the form. So, "afterlife.php?realworld=1" (which I assume is the page if you have not yet entered Valhalla) will save the last ping as "afterlife.php".
    Which we have no specific support for.
    This is untested. I'd like to see it myself. Maybe in a week.
 
Top