Ash mechanics

[fronobulax]

Not sure where this goes nor has my search fu pointed me anywhere useful. Apologies in advance if I'm just being dense and wasting people's time. Just point me to the right place...

I've been pushing the envelope with my DCQuest script and seen some things that bother me. At a high level the script loops through each item. If the item can be displayed then it uses code borrowed from zarqon (Thanks, again!) to query the Jicken Wings collection database to determine a rank on the leaderboard. Since Jicken Wings updates daily, there is some caching code so that server is only hit if there is no entry in the cache or something has changed.

As a rough measure of size there are about 4000 items in my display case and approximately 1000 of them are present in quantities greater than one.

When I first wrote the script I had a sense that the collection rank of something there was only one of was uninteresting so Jicken Wings or the cache were only checked if there was more than one item. Under those conditions the script runs in an acceptable 15 minutes or less, depending upon he state of the cache. However, I discovered that for some items, having one does place on a leaderboard so I flipped the switch to check everything in the DC.

Initially, the script appeared to be doing nothing so I tweaked the verbosity and wrote the cache to disk more frequently.

Script reports that it is checking an item and uses a different message whether the cache or the Jicken Wings site is being used. After running for about 30 minutes, the script appears to stop and stay at the same item. Using the mafia Stop button seems to do something including trigger mafia's relogin actions. Under what circumstances does mafia log out due to inactivity? Is there a way for a script to tell mafia it is active even if the script isn't actually hitting KoL servers? One way to explain what I saw is that mafia logged out of KoL and the script, for reasons unknown to me, was waiting for a response from KoL that it obviously was not getting.

An alternative explanation, although not as likely based upon what happened when I restarted things, is that Jicken Wings took offense at the number of times I hit their server and stopped answering or delayed the answer. This leads to the question - is there any kind of trace functionality or something else that would tell me what line in my script was currently being executed or what command was causing a wait?

I noticed when I aborted the script it did not always run cleanly when I restarted. What is the best way to stop a running script? Is there an easier way to clean up afterward than just just shutting down mafia and restarting? Are there best practices that make scripts easier to clean up after?

Sometimes I would start a script and get a message about something already running and that the script was Queued. Is there any documentation about this? Can I view the queue or delete entries from it?

Thanks.

 

[lostcalpolydude]

The easiest way to stay logged in is to be in chat. Mafia isn't logging you out of KoL; KoL is ending your session for being inactive and mafia doesn't know it.

 

[mredge73]

I didn't think that mafia logged you out due to inactivity but kol did. Correct me if I am wrong. A simple cli_execute("chat"); will open the chat panel and should keep you online.
Regardless, I usually hit the server every 3 minutes with my clan bots to make sure they stay online.

I do not stop a buggy script with the stop button, I usually abort although it doesn't always work if I am running multiple scripts at the same time.
Sometimes I hang mafia so bad with a buggy ash script that a total restart needs to be done to get it working again.
Sounds like you got one of these.

As far as knowing what line caused the problem, I don't think there is a way without building lots of error checking and print commands into your script.

 

[zarqon]

I doubt KoL's logged-in timeout is the issue; mafia will automatically log you in if you try to grab a KoL page after being logged out by KoL.

I would recommend adding:

1) something to the caching so that if you only have one of an item and don't rank, it will skip that item from then on. Also, if you're not already, write the cache to disk after each item, so if you abort the script midway, you'll be using cached values after that.
2) lots of high-verbosity vprint()'s to your script, denoting the beginning and end of each function, return values being passed, etc., perhaps one by one, until you can determine where the problem is happening.

 

[fronobulax]

@lost - Chat? What's that? I'm not much of a Heart I will try it as a heartbeat or keep alive since one way to explain what I see is that something (mafia or KoL) thinks I am inactive and logs me out. I don't really care who thinks I am inactive, I just wish their definition of activity matched mine.

@mredge - What are you calling "abort"? When I talked about stopping what I meant was the "Stop Now" button on the Adventure screen. Is there something else you are doing? A gCLI command I have missed, for example?

@zarqon - One hypothesis is that, because I am running an ash script, something gets bypassed and the script asks for a page without triggering the relogin. I have no reason to believe that other than it could explain what I am seeing.

I realized that there were items where I did rank with exactly one. So I want the script to run once and check every rank. Once that happens there is no point in checking rank on a regular basis but it has to work once to handle the initialization case or the case where someone just blows away the cache file. Early in my debugging, I did realize when I aborted and failed to cache I was gathering the same data all over again, so now I do write out the cache periodically. I was writing after every 10 items but I suspect that is a habit driven by performance issues that are not present, so I will make the frequency of writes tweakable and set it to 1 until I have reason to change it.

I will break down and add some more feedback since that seems to be the only way to go. The last line I see is a status message about getting updated info. With the prints as they are now it could be hanging on the call to Jicken Wings or it could have a problem dealing with a subsequent entry in $items[]. Now that I know there is not a viable trace functionality I will add messages and narrow things down.

Thanks all.

 

[mredge73]

@mredge - What are you calling "abort"? When I talked about stopping what I meant was the "Stop Now" button on the Adventure screen. Is there something else you are doing? A gCLI command I have missed, for example?

type "abort" in the cli should halt all script activity
you may have to do it more than once if you are running multiple scripts at the same time.

 

[Winterbay]

I've always thought that typing abort in the gCLI is the same as pressing the Stop Now! button, it at least gives the same kind of message when you do.

 

[Camber]

Now that I know there is not a viable trace functionality I will add messages and narrow things down.

You can always turn on debug, run the script, turn debug off and look at the debug log. It is a mess with lots of data, but it is a last resort to debugging a script.

 

[Veracity]

Now that I know there is not a viable trace functionality I will add messages and narrow things down.

Considering how hard I worked to add ASH tracing to the debug log, that's rather insulting.

Perhaps it would be more "viable" if you could do it without the debug log; it would certainly be smaller, since you wouldn't have all the request and replies and such, but without those, you can't necessarily tell why something failed, for example.

 

[slyz]

Maybe you can can also try out the profile CLI command. It works even if you abort the script mid-way.

For it to be useful, you probably should do more separate functions to call, but it would give you the culprit.

More info here.

 

[fronobulax]

Considering how hard I worked to add ASH tracing to the debug log, that's rather insulting.

I'll apologize. What we have here may be differing definitions or operator error, but not a deliberate insult.

When I talked about trace functionality, what I had in mind was something akin to using the command line switches -x -X -v and -V with tcsh, for example. Using those options I can get a line of script source printed out before it executes, after it executes and before or after any substitutions that are made. I have found such execution tracing capability to be easier to use then embedded debug prints.

When I tried turning on debug prints with a different script, I had lots of information (i.e. HTML) tracing the exchanges between mafia and KoL but I failed to notice any way to relate that to the script I was debugging. Since the script in question did not hit the KoL servers once the display case and inventory were refreshed, I jumped to the conclusion that turning on debug was not going to help me. Since there was a bottle of wine that was full when I started the exercise and empty at the end, it is quite possible that what I did, and what I now think I did, were different or that I failed to notice that the answers were already being logged.

Bottom line: I'm sorry and I will turn on debug printing.

 

[Veracity]

Here is an example of tracing. The script:

string [int] map;
map[1] = "abc";
map[3] = "def";
map[100] = "yowza!";

foreach key, val in map
  print( "key = " + key + " maps to " + val );

has no calls to KoL. Hence, the debug log will not be cluttered with HTML. When I execute it, I see this:

> trt

key = 1 maps to abc
key = 3 maps to def
key = 100 maps to yowza!

and have the following in the debug log:

> trt

<SCOPE>
   <TYPES>
   <VARIABLES>
      <VAR string [int] map>
   <FUNCTIONS>
   <COMMANDS>
      <ASSIGN map>
         <VALUE string [int] [<initial value>]>
      <ASSIGN map[]>
         <KEY>
            <VALUE int [1]>
         <VALUE string [abc]>
      <ASSIGN map[]>
         <KEY>
            <VALUE int [3]>
         <VALUE string [def]>
      <ASSIGN map[]>
         <KEY>
            <VALUE int [100]>
         <VALUE string [yowza!]>
      <FOREACH>
         <VARREF> key
         <VARREF> val
         <VARREF> map
         <SCOPE>
            <TYPES>
            <VARIABLES>
               <VAR int key>
               <VAR string val>
            <FUNCTIONS>
            <COMMANDS>
               <CALL print>
                  <OPER +>
                     <OPER +>
                        <OPER +>
                           <VALUE string [key = ]>
                           <VARREF> key
                        <VALUE string [ maps to ]>
                     <VARREF> val
Executing top-level commands
   [NORMAL] <- void
      Eval: abc
      Set: abc
      AREF: aggregate string [int]
         Key #1: 1
         [NORMAL] <- 1
      ASET: "abc"
   [NORMAL] <- void
      Eval: def
      Set: def
      AREF: aggregate string [int]
         Key #1: 3
         [NORMAL] <- 3
      ASET: "def"
   [NORMAL] <- void
      Eval: yowza!
      Set: yowza!
      AREF: aggregate string [int]
         Key #1: 100
         [NORMAL] <- 100
      ASET: "yowza!"
   [NORMAL] <- void
      foreach
      Key #0: 1
            Param #1: ( ( ( "key = " + key ) + " maps to " ) + val )
               Operator: +
                  Operand 1: ( ( "key = " + key ) + " maps to " )
                     Operator: +
                        Operand 1: ( "key = " + key )
                           Operator: +
                              Operand 1: key = 
                              [NORMAL] <- "key = "
                              Operand 2: key
                              [NORMAL] <- 1
                           <- key = 1
                        [NORMAL] <- "key = 1"
                        Operand 2:  maps to 
                        [NORMAL] <- " maps to "
                     <- key = 1 maps to 
                  [NORMAL] <- "key = 1 maps to "
                  Operand 2: val
                  [NORMAL] <- "abc"
               <- key = 1 maps to abc
            [NORMAL] <- "key = 1 maps to abc"
            Entering function print
key = 1 maps to abc
            Function print returned: void
         [NORMAL] <- void
      Key #1: 3
            Param #1: ( ( ( "key = " + key ) + " maps to " ) + val )
               Operator: +
                  Operand 1: ( ( "key = " + key ) + " maps to " )
                     Operator: +
                        Operand 1: ( "key = " + key )
                           Operator: +
                              Operand 1: key = 
                              [NORMAL] <- "key = "
                              Operand 2: key
                              [NORMAL] <- 3
                           <- key = 3
                        [NORMAL] <- "key = 3"
                        Operand 2:  maps to 
                        [NORMAL] <- " maps to "
                     <- key = 3 maps to 
                  [NORMAL] <- "key = 3 maps to "
                  Operand 2: val
                  [NORMAL] <- "def"
               <- key = 3 maps to def
            [NORMAL] <- "key = 3 maps to def"
            Entering function print
key = 3 maps to def
            Function print returned: void
         [NORMAL] <- void
      Key #2: 100
            Param #1: ( ( ( "key = " + key ) + " maps to " ) + val )
               Operator: +
                  Operand 1: ( ( "key = " + key ) + " maps to " )
                     Operator: +
                        Operand 1: ( "key = " + key )
                           Operator: +
                              Operand 1: key = 
                              [NORMAL] <- "key = "
                              Operand 2: key
                              [NORMAL] <- 100
                           <- key = 100
                        [NORMAL] <- "key = 100"
                        Operand 2:  maps to 
                        [NORMAL] <- " maps to "
                     <- key = 100 maps to 
                  [NORMAL] <- "key = 100 maps to "
                  Operand 2: val
                  [NORMAL] <- "yowza!"
               <- key = 100 maps to yowza!
            [NORMAL] <- "key = 100 maps to yowza!"
            Entering function print
key = 100 maps to yowza!
            Function print returned: void
         [NORMAL] <- void
   [NORMAL] <- void

Notice that it starts out with the parse tree, and follows it up with the trace. It's definitely more verbose than "one line per line of script" since it shows the inputs and outputs of every function call and even every operator in an expression.

 

[lostcalpolydude]

@lost - Chat? What's that? I'm not much of a Heart I will try it as a heartbeat or keep alive since one way to explain what I see is that something (mafia or KoL) thinks I am inactive and logs me out. I don't really care who thinks I am inactive, I just wish their definition of activity matched mine.

You might like /kwe then, since there's no chatting there anyway.

 

[fronobulax]

Update. I finally did find the script parse tree and related trace info in the debug log. I admit I personally find it difficult to interpret but it is there.

My speculation that the problem was related to KoL or mafia timing out is incorrect, so I didn't experiment with chat.

What I did find, with debug prints inserted, was an edge case that the code zarqon shared did not handle well and went into a loop. If your collection ranks then the code tries to figure out what you need to advance in rank. Unfortunately, there are a couple of items, such as the bucket of anniversary lard where all 1000 entries in the collection leaderboard are tied for the top position.

Thanks for the comments and help and I'm still sorry for an unfortunate choice of words to describe a feature that is present, but not well know, veracity.