TeensyMud - 'A ruby mud server.'

Subject: Account & cursor position issues
Wiki | Forums | Repository | Sign Up | Login | New Topic | Recent Posts | Forums RSS
Subject: Account & cursor position issues
Author: Massaria
Posted: 03/21/2006 01:09PM
Yay! A total of TWO new teensies to molest... ehrm, well - onwards.

I've installed 2.9 and it's running without a single change so far, but I've encountered some inexplicable behaviour. The problems may be related somehow, indeed it seems so, but there are 3 distinct points that I can see:

1) The connect greeting varies
Some times it'll show a bunch of things (big-ass red TeensyMud, lines demonstrating underlining, blinking, bold etc., "CR testblank it out" (twice)), at other times it'll just show the BANNER. I can't detect any particular pattern to it.
Possibly it has to do with creating the very first account?

2) The cursor position isn't correct
When it does display everything at login, it seems the cursor position gets mixed up somehow. It writes over old lines, skips over others and generally creates a very confusing login experience.

3) The prompt may or may not be there
Once I'm in the game with a char, it seems arbitrary whether or not the prompt of (account)[character] is there (nice touch btw, as is the whole account system. me like! (oh, except it would be nice to quit to the account menu, or perhaps have another command do that)).

I haven't delved very deep into the new release yet, but it's difinitely a big thumbs-up so far. I'll get back to you on those 2.10 priorities when I get a better hold of the new stuff.
I'll try to find some pattern in the above, see it I can't give you something more to go on.

Thanks
Tobias

_____________
EDIT:

Ah. Wasn't such a big mystery after all. The BANNER-only connection screen and lack of (account)[char] prompt is the result of a reconnect command from a char that's already online... or, that is one reason at least ;-)

Also, resizing the screen size while in the connection-greeting makes it go totally blank, text is nowhere to be found (on zMud).

Another oddity, perhaps related to the BANNER-only greeting, is an error I get when trying to kill the server:

06-03-21 19:19:45 [ WARN] (Engine) Signal caught request to shutdown.
06-03-21 19:19:45 [ INFO] (Reactor) Reactor#shutdown: Reactor shutting down
06-03-21 19:19:45 [ INFO] (Engine) Saving world...
06-03-21 19:19:45 [ERROR] (Connection) (136511624) Connection#handle_input disconnecting
06-03-21 19:19:45 [ERROR] (Connection) Caught SystemExit?: exit
./lib/engine/engine.rb:134:in `exit'
./lib/engine/engine.rb:134:in `graceful_shutdown'
./lib/engine/engine.rb:125:in `handle_signal'
./lib/network/sockio.rb:37:in `read'
./lib/network/connection.rb:76:in `handle_input'
./lib/network/reactor.rb:127:in `poll'
./lib/network/reactor.rb:124:in `poll'
06-03-21 19:19:45 [ INFO] (Connection) (136511624) Connection 'localhost(127.0.0.1)' closing
06-03-21 19:19:45 [ INFO] (Connection) (136659152) Connection 'localhost(127.0.0.1)' closing
06-03-21 19:19:45 [ INFO] (Connection) (136773776) Connection 'localhost(127.0.0.1)' closing
06-03-21 19:19:45 [ INFO] (Connection) (136612676) Connection 'localhost(127.0.0.1)' closing
06-03-21 19:22:28 [ WARN] (Engine) Signal caught request to shutdown.
06-03-21 19:22:28 [ INFO] (Reactor) Reactor#shutdown: Reactor shutting down
06-03-21 19:22:28 [ INFO] (Engine) Saving world...

I didn't have any characters connected at the time. Go figure... Please :-)
reply
Subject: Account & cursor position issues
Author: Tyche
Posted: 03/22/2006 10:04AM
Massaria wrote:
> 1) The connect greeting varies
> Some times it'll show a bunch of things (big-ass red TeensyMud, lines demonstrating underlining, blinking, bold etc., "CR testblank it out" (twice)), at other times it'll just show the BANNER. I can't detect any particular pattern to it.
> Possibly it has to do with creating the very first account?

It has to do with VT100 detection. I would suspect that Zmud has a similar problem to the one SimpleMU? has. That is it doesn't return to the start of the terminal list for TTYPE negotiation unless you close the session or the client. As I don't have a modern Zmud, I have no way of testing anything other than the older versions.

If you comment out lines 401-408 of TelnetFilter?.rb you might be able to get rid of the VT100 stuff for Zmud with the side effect of putting XP Telnet sessions into VTNT mode. 
          # short-circuit choice because of Windows telnet client
          if data[1..-1].downcase == 'vt100'
            @ttype << data[1..-1]
            @pstack.terminal = 'vt100'
            log.debug("(#{@pstack.conn.object_id}) Terminal choice - #{@pstack.terminal} in list #{@ttype.inspect}")
          end


I added the LOGO screen in line 106 of Account for testing clients. So far the only client that can parse everything correctly is Reflections. If you saw "CR testblank it out" then that means Zmud doesn't handle CR-NUL correctly. It's something that doesn't come up normally, but I added the tests as a result of a discussion on TMC. Version.rb has both the BANNER and LOGO now so that's where you'd delete the stuff.

In general most of the clients nicely swallow up VT codes that they don't support.

\e[40G40\e[20G20 <--- horizontal position
\e[1mbold\e[m
\e[2mdark\e[m
\e[4munderline\e[m
\e[5mblinking\e[m
\e[7mitalics\e[m
\e[8mhidden\e[m<-hidden?

Bold and underline seems to be well supported. The horizontal position code gives Mushclient fits. I don't detect Mushclient as VT100 though. Scandum has said the current Zmud has pretty good VT100 support. The 4.58 version I tested (see ClientData) does not.

> 2) The cursor position isn't correct
> When it does display everything at login, it seems the cursor position gets mixed up somehow. It writes over old lines, skips over others and generally creates a very confusing login experience.

I'll look into this. This is probably a regression. I can see that GNU Telnet is doing carriage returns and writing over the same line and XP Telnet is doing carriage return and line feeds.

> 3) The prompt may or may not be there
> Once I'm in the game with a char, it seems arbitrary whether or not the prompt of (account)[character] is there (nice touch btw, as is the whole account system. me like! (oh, except it would be nice to quit to the account menu, or perhaps have another command do that)).

It seems to be always there on every client I tested. Don't read anything into what is displayed. I just dumped the Account's @mode variable and character name into it. Which happens to be the previous @mode. The prompt code is on Account#prompt. You probably want to put meaningful stuff into it. Note there isn't any prompt for non-VT clients.

I'll definately change quit to go back to the menu if the accounts option is on.

> I'll try to find some pattern in the above, see it I can't give you something more to go on.

The sort of stuff I put on ClientData would be helpful. Especially the log of the terminal information sent during repeated reconnects. :-)


> Ah. Wasn't such a big mystery after all. The BANNER-only connection screen and lack of (account)[char] prompt is the result of a reconnect command from a char that's already online... or, that is one reason at least ;-)
>
> Also, resizing the screen size while in the connection-greeting makes it go totally blank, text is nowhere to be found (on zMud).

Yes it should on all clients.
In Account around line 100 or so...
# Issued when a NAWS event occurs
# Currently this clears and resets the screen. Ideally it should attempt
# to redraw it.
Currently I have no way of redrawing the screen yet. And if I don't reset the vertical dimensions then the prompt will be in the middle of the screen or off the screen after a NAWS event. Clearing it seemed the logical thing to do at this point.

> Another oddity, perhaps related to the BANNER-only greeting, is an error I get when trying to kill the server:
>
> 06-03-21 19:19:45 [ERROR] (Connection) Caught SystemExit?: exit
> ./lib/engine/engine.rb:134:in `exit'
> ./lib/engine/engine.rb:134:in `graceful_shutdown'
> ./lib/engine/engine.rb:125:in `handle_signal'
> ./lib/network/sockio.rb:37:in `read'
> ./lib/network/connection.rb:76:in `handle_input'
> ./lib/network/reactor.rb:127:in `poll'
> ./lib/network/reactor.rb:124:in `poll'

I couldn't duplicate the above. What OS and Ruby version?

One other thing I found is that you can now create as many characters with the same name as you want. That might get confusing. ;-)

reply
Subject: Account & cursor position issues
Author: Massaria
Posted: 03/22/2006 01:03PM

A comprehensive answer as always. Thanks.

Tyche wrote:
>
> I added the LOGO screen in line 106 of Account for testing clients. So far the only client that can parse everything correctly is Reflections. If you saw "CR testblank it out" then that means Zmud doesn't handle CR-NUL correctly.

When you state it with such conviction, I guess I'll have to tell Zugg.
Could you be more specific in what's wrong (without doing his work for him, I need you for that ;-)?

>
> > 2) The cursor position isn't correct
> > When it does display everything at login, it seems the cursor position gets mixed up somehow. It writes over old lines, skips over others and generally creates a very confusing login experience.
>
> I'll look into this. This is probably a regression. I can see that GNU Telnet is doing carriage returns and writing over the same line and XP Telnet is doing carriage return and line feeds.

Another thing I noticed was that it's stopped echoing back my command.
typing 'say hi' will produce

You say, "hi"

not...

say hi
You say, "hi"


> > 3) The prompt may or may not be there
> > Once I'm in the game with a char, it seems arbitrary whether or not the prompt of (account)[character] is there (nice touch btw, as is the whole account system. me like! (oh, except it would be nice to quit to the account menu, or perhaps have another command do that)).
>
> It seems to be always there on every client I tested.

dang. This is pretty serious in my eyes. I'll see if I can dig up some more on this.

> The sort of stuff I put on ClientData would be helpful. Especially the log of the terminal information sent during repeated reconnects. :-)
>

I'm not sure what my server configuration is. I remember seeing it a few times, but I suspect it'll take quite a while to find the right part. I think you made a post about it, or was it a doc or a commentary... Nudge me on, will you?

@status
Terminal: vt100
Terminal size: 130 X 52
Colors toggled OFF
Echo is ON
ZMP is OFF

I'll look into that log.

BTW, I think changing the logging from those three seperate files which rotated every day was a mistake. Don't you find they get unwieldy?

>
> I couldn't duplicate the above. What OS and Ruby version?
>

I'm using the one-click installer, ruby184-16p3, on an XP proff., version 2002 with service pack 2... Danish.
Yeah, I think that's all of it ;-)

> One other thing I found is that you can now create as many characters with the same name as you want. That might get confusing. ;-)

Right. I wanted to mention that. Slipped by me.

reply
Subject: Account & cursor position issues
Author: Massaria
Posted: 03/22/2006 01:35PM
Alright, in the spirit of more = better, here is the whole log of a session with three reconnections.

The prompt disappeared after the first reconnection, but was fine upon the initial login.

Seems my server configuration equals the one you listed in ClientData after all.

06-03-22 18:35:48 [DEBUG] (Engine) Configuration: {"logfile"=>"logs/server.log", "server_type"=>:server, "account_system"=>true, "safe_read"=>true, "cache_size"=>1000, "server_io"=>:sockio, "object_interface"=>["objects"], "props_are_accessors_only"=>false, "dbfile"=>"db/world", "character_limit"=>10, "server_negotiation"=>[:sga, :echo, :naws, :ttype, :zmp], "guest_accounts"=>true, "verbose"=>false, "dbtype"=>:yaml, "character_interface"=>["teensy", "tiny"], "server_port"=>4000, "home"=>1, "trace"=>false, "server_filters"=>[:telnetfilter, :terminalfilter, :colorfilter], "cache_width"=>23, "cache_depth"=>7}
06-03-22 18:35:48 [ INFO] (YamlStore?) Loading world...
06-03-22 18:35:48 [ INFO] (YamlStore?) Database 'db/world.yaml' loaded...highest id = 7.
06-03-22 18:35:48 [ INFO] (Command) Loading commands...
06-03-22 18:35:48 [ INFO] (Command) Done.
06-03-22 18:35:48 [ INFO] (World) Starting Timer...
06-03-22 18:35:48 [ INFO] (World) World initialized.
06-03-22 18:35:48 [ INFO] (EventManager?) Event manager starting...
06-03-22 18:35:48 [ INFO] (Engine) Booting server on port 4000
06-03-22 18:35:48 [DEBUG] (Reactor) #
06-03-22 18:35:48 [ INFO] (Engine) TMUD is ready
06-03-22 18:35:54 [ INFO] (Connection) (135774020) New Connection on 'localhost(127.0.0.1)'
06-03-22 18:35:54 [DEBUG] (TelnetFilter?) (135774020) Offered Telnet option 93 set to true
06-03-22 18:35:54 [DEBUG] (TelnetFilter?) (135774020) Offered Telnet option 1 set to true
06-03-22 18:35:54 [DEBUG] (TelnetFilter?) (135774020) Requested Telnet option 24 set to true
06-03-22 18:35:54 [DEBUG] (TelnetFilter?) (135774020) Offered Telnet option 3 set to true
06-03-22 18:35:54 [DEBUG] (TelnetFilter?) (135774020) Requested Telnet option 31 set to true
06-03-22 18:35:54 [ INFO] (Acceptor) (135774020) Connection accepted.
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Client requests Telnet option 93 set to false
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet negotiation: agreed to disable option 93
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Client requests Telnet option 1 set to true
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet negotiation: agreed to enable option 1
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Client replies to Telnet option 24 set to true
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet negotiation: agreed to enable option 24
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Client requests Telnet option 3 set to true
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet negotiation: agreed to enable option 3
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Client replies to Telnet option 31 set to true
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet negotiation: agreed to enable option 31
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal width 130 / height 52
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal type - zmud
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal type - vt100
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal choice - vt100 in list ["zmud", "vt100"]
06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet init_subneg option - Timed out after 32 tries.
06-03-22 19:09:35 [ INFO] (Connection) (136756136) New Connection on 'localhost(127.0.0.1)'
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Offered Telnet option 93 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Offered Telnet option 1 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Requested Telnet option 24 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Offered Telnet option 3 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Requested Telnet option 31 set to true
06-03-22 19:09:35 [ INFO] (Acceptor) (136756136) Connection accepted.
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet init_subneg option - Timed out after 32 tries.
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client requests Telnet option 93 set to false
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to disable option 93
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client requests Telnet option 1 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to enable option 1
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client replies to Telnet option 24 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to enable option 24
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client requests Telnet option 3 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to enable option 3
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client replies to Telnet option 31 set to true
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to enable option 31
06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Terminal width 130 / height 52
06-03-22 19:09:59 [ INFO] (Connection) (135774020) Connection 'localhost(127.0.0.1)' closing for reconnection
06-03-22 19:10:43 [ INFO] (Connection) (136742792) New Connection on 'localhost(127.0.0.1)'
06-03-22 19:10:43 [DEBUG] (TelnetFilter?) (136742792) Offered Telnet option 93 set to true
06-03-22 19:10:43 [DEBUG] (TelnetFilter?) (136742792) Offered Telnet option 1 set to true
06-03-22 19:10:43 [DEBUG] (TelnetFilter?) (136742792) Requested Telnet option 24 set to true
06-03-22 19:10:43 [DEBUG] (TelnetFilter?) (136742792) Offered Telnet option 3 set to true
06-03-22 19:10:43 [DEBUG] (TelnetFilter?) (136742792) Requested Telnet option 31 set to true
06-03-22 19:10:43 [ INFO] (Acceptor) (136742792) Connection accepted.
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Telnet init_subneg option - Timed out after 32 tries.
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Client requests Telnet option 93 set to false
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Telnet negotiation: agreed to disable option 93
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Client requests Telnet option 1 set to true
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Telnet negotiation: agreed to enable option 1
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Client replies to Telnet option 24 set to true
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Telnet negotiation: agreed to enable option 24
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Client requests Telnet option 3 set to true
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Telnet negotiation: agreed to enable option 3
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Client replies to Telnet option 31 set to true
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Telnet negotiation: agreed to enable option 31
06-03-22 19:10:44 [DEBUG] (TelnetFilter?) (136742792) Terminal width 130 / height 52
06-03-22 19:10:49 [ INFO] (Connection) (136756136) Connection 'localhost(127.0.0.1)' closing for reconnection
06-03-22 19:11:15 [ INFO] (Connection) (136930100) New Connection on 'localhost(127.0.0.1)'
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Offered Telnet option 93 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Offered Telnet option 1 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Requested Telnet option 24 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Offered Telnet option 3 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Requested Telnet option 31 set to true
06-03-22 19:11:15 [ INFO] (Acceptor) (136930100) Connection accepted.
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Telnet init_subneg option - Timed out after 32 tries.
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Client requests Telnet option 93 set to false
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Telnet negotiation: agreed to disable option 93
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Client requests Telnet option 1 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Telnet negotiation: agreed to enable option 1
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Client replies to Telnet option 24 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Telnet negotiation: agreed to enable option 24
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Client requests Telnet option 3 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Telnet negotiation: agreed to enable option 3
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Client replies to Telnet option 31 set to true
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Telnet negotiation: agreed to enable option 31
06-03-22 19:11:15 [DEBUG] (TelnetFilter?) (136930100) Terminal width 130 / height 52
06-03-22 19:11:22 [ INFO] (Connection) (136742792) Connection 'localhost(127.0.0.1)' closing for reconnection
06-03-22 19:11:55 [ INFO] (Connection) (136930100) Connection 'localhost(127.0.0.1)' closing
06-03-22 19:12:02 [ WARN] (Engine) Signal caught request to shutdown.
06-03-22 19:12:02 [ INFO] (Reactor) Reactor#shutdown: Reactor shutting down
06-03-22 19:12:02 [ INFO] (Engine) Saving world...

I doubt it's related to the missing prompt, but as I create a new char in the last reconnection and enter play with him (as opposed to the former, where I entered play with the first char I made), this results:

Enter character name> newchar
newchar

Welcome Newchar@localhost!
Newchar has connected.
Newchar has connected.
Newchar has connected.
(1) Home
This is home.

Test is here.
Exits:
None.
quit
quit
Bye!

Of course, as we've been over before, 'Test' wasn't there at all. And it seems my quit command did get echoed this time around. Seems it doesn't echo on the initial login, but on all the subsequent.
Anyways, it seems the privious connections lingers somehow, getting mixed up with my new char, or... *shuts up to accomodate those who know what they're talking about*

I'd be happy to provide more info if you need something specific.

Mass.
reply
Subject: Account & cursor position issues
Author: Tyche
Posted: 03/25/2006 04:36AM
Massaria wrote:
> 06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal width 130 / height 52
> 06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal type - zmud
> 06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal type - vt100
> 06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Terminal choice - vt100 in list ["zmud", "vt100"]
> 06-03-22 18:35:59 [DEBUG] (TelnetFilter?) (135774020) Telnet init_subneg option - Timed out after 32 tries.
...
> 06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client requests Telnet option 3 set to true
> 06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to enable option 3
> 06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Client replies to Telnet option 31 set to true
> 06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Telnet negotiation: agreed to enable option 31
> 06-03-22 19:09:35 [DEBUG] (TelnetFilter?) (136756136) Terminal width 130 / height 52

It looks like terminal negotiation is only done once and not on reconnections. I can't tell whether it's me not sending it or zmud not responding.

Uncommenting :debugfilter in the config and running the same test ought to show
exactly what's happening.



server_filters:
- :debugfilter
- :telnetfilter



reply
Subject: Account & cursor position issues
Author: Tyche
Posted: 03/25/2006 04:47AM
Massaria wrote:
>
> BTW, I think changing the logging from those three seperate files which rotated every day was a mistake. Don't you find they get unwieldy?
>

Yeah the Log4r class in it now doesn't support the rolling logs, and the old Logger didn't support the class level logging to multiple logs. Nearly all the classes have... logger 'DEBUG' in them and produce gobs of output. Changing it to logger 'INFO' will reduce the output quite a bit.

reply
Subject: Account & cursor position issues
Author: Massaria
Posted: 03/26/2006 12:58PM
>
> It looks like terminal negotiation is only done once and not on reconnections. I can't tell whether it's me not sending it or zmud not responding.
>
> Uncommenting :debugfilter in the config and running the same test ought to show exactly what's happening.
>
>

Here's the log of a reconnection where the prompt was lost afterwards:

...
06-03-26 19:51:54 [ INFO] (Engine) TMUD is ready
06-03-26 19:52:01 [ INFO] (Connection) (136894460) New Connection on 'localhost(127.0.0.1)'
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Offered Telnet option 93 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Offered Telnet option 1 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Requested Telnet option 24 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Offered Telnet option 3 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Requested Telnet option 31 set to true
06-03-26 19:52:01 [ INFO] (Acceptor) (136894460) Connection accepted.
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\377\373]\377\373\001\377\375\030\377\373\003\377\375\037"
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) INPUT "\377\376]"
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Client requests Telnet option 93 set to false
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Telnet negotiation: agreed to disable option 93
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) INPUT "\377\375\001\377\373\030\377\375\003\377\373\037\377\372\037\000g\0004\377\360"
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Client requests Telnet option 1 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Telnet negotiation: agreed to enable option 1
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Client replies to Telnet option 24 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Telnet negotiation: agreed to enable option 24
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Client requests Telnet option 3 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Telnet negotiation: agreed to enable option 3
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Client replies to Telnet option 31 set to true
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Telnet negotiation: agreed to enable option 31
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Terminal width 103 / height 52
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\377\372\030\001\377\360"
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) INPUT "\377\372\030\000zmud\377\360"
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Terminal type - zmud
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\377\372\030\001\377\360"
06-03-26 19:52:01 [DEBUG] (DebugFilter?) (136894460) INPUT "\377\372\030\000vt100\377\360"
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Terminal type - vt100
06-03-26 19:52:01 [DEBUG] (TelnetFilter?) (136894460) Terminal choice - vt100 in list ["zmud", "vt100"]
06-03-26 19:52:06 [DEBUG] (TelnetFilter?) (136894460) Telnet init_subneg option - Timed out after 32 tries.
06-03-26 19:52:06 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\e7\e[49;1H\r\n\r\n This is TeensyMUD? version 2.9.0\r\n\r\n Copyright (C) 2005, 2006 by Jon A. Lambert\r\n Released under the terms of the TeensyMUD? Public License\r\n\r\n\e8\e[50;1H \e[51;1H\e[2K()[initialize]\e[52;1H\e[2K> \e7\e[49;1Hlogin> \e8\e[50;1H \e[51;1H\e[2K()[initialize]\e[52;1H\e[2K> "
06-03-26 19:52:06 [DEBUG] (DebugFilter?) (136894460) INPUT "ME!\r\n"
06-03-26 19:52:06 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\e[2K\e7\e[49;1Hpassword> \e8\e[50;1H \e[51;1H\e[2K()[name]\e[52;1H\e[2K> "
06-03-26 19:52:07 [DEBUG] (DebugFilter?) (136894460) INPUT "ME!\r\n"
06-03-26 19:52:07 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\e7\e[49;1H1) Create a character\r\n2) Play\r\nQ) Quit\r\n> \e8\e[50;1H \e[51;1H\e[2K(Me!)[]\e[52;1H\e[2K> "
06-03-26 19:52:11 [DEBUG] (DebugFilter?) (136894460) INPUT "1\r\n"
06-03-26 19:52:11 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\e7\e[49;1HEnter character name> \e8\e[50;1H \e[51;1H\e[2K(Me!)[menu]\e[52;1H\e[2K> "
06-03-26 19:52:17 [DEBUG] (DebugFilter?) (136894460) INPUT "me_char\r\n"
06-03-26 19:52:17 [DEBUG] (DebugFilter?) (136894460) OUTPUT "\e7\e[49;1HWelcome Me_char@localhost!\r\n\e8\e[50;1H \e[51;1H\e[2K(Me!)[menucr]\e[52;1H\e[2K> \e[50;1H \e[51;1H\e[2K(Me!)[menucr]\e[52;1H\e[2K> \e7\e[49;1H(1) Home\r\nThis is home.\r\n\r\n\e8\e[50;1H \e[51;1H\e[2K(Me!)[playing]\e[52;1H\e[2K> \e7\e[49;1HExits:\r\nNone.\r\n\e8\e[50;1H \e[51;1H\e[2K(Me!)[playing]\e[52;1H\e[2K> "
06-03-26 19:52:27 [ INFO] (Connection) (136828412) New Connection on 'localhost(127.0.0.1)'
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Offered Telnet option 93 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Offered Telnet option 1 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Requested Telnet option 24 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Offered Telnet option 3 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Requested Telnet option 31 set to true
06-03-26 19:52:27 [ INFO] (Acceptor) (136828412) Connection accepted.
06-03-26 19:52:27 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\377\373]\377\373\001\377\375\030\377\373\003\377\375\037"
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Telnet init_subneg option - Timed out after 32 tries.
06-03-26 19:52:27 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\n\r\n This is TeensyMUD? version 2.9.0\r\n\r\n Copyright (C) 2005, 2006 by Jon A. Lambert\r\n Released under the terms of the TeensyMUD? Public License\r\n\r\n\r\nlogin> "
06-03-26 19:52:27 [DEBUG] (DebugFilter?) (136828412) INPUT "\377\376]\377\375\001\377\373\030\377\375\003\377\373\037\377\372\037\000g\0004\377\360"
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Client requests Telnet option 93 set to false
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Telnet negotiation: agreed to disable option 93
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Client requests Telnet option 1 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Telnet negotiation: agreed to enable option 1
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Client replies to Telnet option 24 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Telnet negotiation: agreed to enable option 24
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Client requests Telnet option 3 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Telnet negotiation: agreed to enable option 3
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Client replies to Telnet option 31 set to true
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Telnet negotiation: agreed to enable option 31
06-03-26 19:52:27 [DEBUG] (TelnetFilter?) (136828412) Terminal width 103 / height 52
06-03-26 19:52:30 [DEBUG] (DebugFilter?) (136828412) INPUT "ME!\r\n"
06-03-26 19:52:31 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\npassword> "
06-03-26 19:52:33 [DEBUG] (DebugFilter?) (136828412) INPUT "me_char\r\n"
06-03-26 19:52:33 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\nSorry wrong password.\r\nlogin> "
06-03-26 19:52:35 [DEBUG] (DebugFilter?) (136828412) INPUT "ME!\r\n"
06-03-26 19:52:35 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\npassword> "
06-03-26 19:52:37 [DEBUG] (DebugFilter?) (136828412) INPUT "ME!\r\n"
06-03-26 19:52:37 [ INFO] (Connection) (136894460) Connection 'localhost(127.0.0.1)' closing for reconnection
06-03-26 19:52:37 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\n1) Create a character\r\n2) Play\r\nQ) Quit\r\n> "
06-03-26 19:52:40 [DEBUG] (DebugFilter?) (136828412) INPUT "1\r\n"
06-03-26 19:52:40 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\nEnter character name> "
06-03-26 19:52:45 [DEBUG] (DebugFilter?) (136828412) INPUT "me_char\r\n"
06-03-26 19:52:45 [DEBUG] (DebugFilter?) (136828412) OUTPUT "\r\nWelcome Me_char@localhost!\r\nMe_char has connected.\r\n(1) Home\r\nThis is home.\r\n\r\nMe_char is here.\r\nExits:\r\nNone.\r\n"
06-03-26 19:53:11 [ WARN] (Engine) Signal caught request to shutdown.
06-03-26 19:53:11 [DEBUG] (DebugFilter?) (136828412) OUTPUT "Shutdown.\r\nBye!\r\n"
06-03-26 19:53:11 [ INFO] (Reactor) Reactor#shutdown: Reactor shutting down
06-03-26 19:53:11 [ INFO] (Engine) Saving world...

Hope it helps. I sure as hell can't figure it.
reply
Subject: Account & cursor position issues
Author: Tyche
Posted: 03/26/2006 07:15PM
Massaria wrote:
>
> Hope it helps. I sure as hell can't figure it.

It sure does. It is definately teensy's problem. Something isn't being reset correctly on the Account. Not sure what, but I'll have a patch shortly.

The :debugfilter does an inspect of exactly what codes are being sent out and in. Very useful, but also very chatty.



reply