Re: [4.0.2 bug] commands not written to history

Re: [4.0.2 bug] commands not written to history

[Bart Schaefer]

[Moved to zsh-workers]

On Jul 21,  3:44pm, Vincent Lefevre wrote:
} Subject: Re: [4.0.2 bug] commands not written to history
}
} This problem occurred again, but this time with a local FS [...]
} Moreover, the command I got after cmd1 was "startx", which means that
} cmd2 (the command that hadn't been written to the history) was the
} last command typed in the shell, like in my previous bug report.

Something that just occurred to me:  You're sure that `cmd2' has run to
completion and the prompt has returned before the shell where you typed
that command exited?  E.g. you didn't type `cmd2' and then while it was
still running, shut down your X server or kill the xterm window?

Here's what you should try next:

Make a directory ~/zhist-debug (call it whatever you like).

Put in your .zshrc the commands:

	date > ~/zhist-debug/startup.$$
	TRAPEXIT() {
	  # Order here is important!
	  fc -WI ~/zhist-debug/unsaved.$$
	  fc -W ~/zhist-debug/complete.$$
	  # This assumes you have GNU `cp'
	  cp -p $HISTFILE ~/zhist-debug/histfile.$$
	}

If there is a `startup' file with none of the other files, then zsh may be
exiting without writing the history at all, which shouldn't matter with
INC_APPEND_HISTORY but might be a clue all the same.

Because zsh writes the history before calling TRAPEXIT, the `unsaved' file
should always be empty.  If it is not, then INC_APPEND_HISTORY is causing
an error when the history is written at exit time.

For the same reason, the modify time of the `histfile' file (copied from
$HISTFILE by `cp -p') should be EARLIER THAN the modify time of the
`complete' file.  If it isn't, then multiple shells are writing to the
histfile almost simultaneously (e.g., because you killed your entire X
session rather than exiting from each individual shell), so zsh may have
a locking problem.  (Note that if you exit from a lot of shells at once,
even if locking is working properly the order in which $HISTFILE gets
updated will be essentially random; obtaining the lock is a race.)

My guess is that `startx' is being inserted into $HISTFILE by your console
login shell at the time the `startx' command finishes, i.e., after all the
xterm shells have shut down.  So none of the `histfile' files except the
one for the console shell should have the `startx' command at the end.  If
`startx' appears near the end of more than one of those files, then the
problem may be that the console shell is incrementally appending `startx'
to $HISTFILE before all the exiting xterm shells have finished saving their
own commands, thus garbling the expected ordering.

If none of these races happened, then the `complete' file should have the
same last $HISTSIZE entries (assuming SAVEHIST > HISTSIZE) as the `histfile'
file, possibly modulo incrementally saved entries from other shells which
may have been in $HISTFILE.  Any unexplained differences may give us a clue.

Finally, by examining the file times of the various files we can tell in
what order the shells are starting and exiting, which may help determine
what sequence of events causes the error.

-- 
Bart Schaefer                                 Brass Lantern Enterprises
http://www.well.com/user/barts              http://www.brasslantern.com

Zsh: http://www.zsh.org | PHPerl Project: http://phperl.sourceforge.net   

Re: [4.0.2 bug] commands not written to history

[Vincent Lefevre]

On Sat, Jul 21, 2001 at 18:32:20 +0000, Bart Schaefer wrote:
> Something that just occurred to me:  You're sure that `cmd2' has run to
> completion and the prompt has returned before the shell where you typed
> that command exited?

Yes, I'm sure that the command has exited. But is it important in my
case? Commands are written to the history before they start.

> Make a directory ~/zhist-debug (call it whatever you like).
> 
> Put in your .zshrc the commands:
> 
> 	date > ~/zhist-debug/startup.$$
> 	TRAPEXIT() {
> 	  # Order here is important!
> 	  fc -WI ~/zhist-debug/unsaved.$$
> 	  fc -W ~/zhist-debug/complete.$$
> 	  # This assumes you have GNU `cp'

OK, no problem as I'm under Linux.

> 	  cp -p $HISTFILE ~/zhist-debug/histfile.$$
> 	}

I've replaced cp by \cp, because I've aliased cp.

> My guess is that `startx' is being inserted into $HISTFILE by your console
> login shell at the time the `startx' command finishes, i.e., after all the
> xterm shells have shut down.

No, it isn't the case.

BTW, a problem could be (but I don't think it is this problem here),
because I ignore immediate dups:

Shell 1: true a
Shell 2: true b
Shell 1: true a
Shell 1: true c

Though after the last "true a", "true c" has been typed immediately
after it, the HISTFILE contains

true a
true b
true c

Is it possible to have immediate dups in the HISTFILE, but not in
the shell history?

-- 
Vincent Lefèvre <vincent@vinc17.org> - Web: <http://www.vinc17.org/> - 100%
validated HTML - Acorn Risc PC, Yellow Pig 17, Championnat International des
Jeux Mathématiques et Logiques, TETRHEX, etc.
Work: CR INRIA - computer arithmetic / SPACES project at LORIA

Re: [4.0.2 bug] commands not written to history

[Bart Schaefer]

On Jul 22,  1:43am, Vincent Lefevre wrote:
}
} Yes, I'm sure that the command has exited. But is it important in my
} case? Commands are written to the history before they start.

Er, right.  I'm confusing what happens when the history is written at
exit with what happens on incremental append.

} BTW, a problem could be (but I don't think it is this problem here)

That's one thing I'm hoping all those different shells' history dumps
will tell us.

} because I ignore immediate dups:
} 
} Shell 1: true a
} Shell 2: true b
} Shell 1: true a
} Shell 1: true c
} 
} Though after the last "true a", "true c" has been typed immediately
} after it, the HISTFILE contains
} 
} true a
} true b
} true c
} 
} Is it possible to have immediate dups in the HISTFILE, but not in
} the shell history?

Not for duplicates occurring in the same shell.  That is, you might get
two `true a' in a row written out by different shells -- though they'd
collapse to one when the $HISTFILE exceeded $SAVEHIST lines by a large
enough margin to cause zsh to re-read/write it -- but in any given shell,
the duplicate is thrown away before the check for unsaved commands is
done.

-- 
Bart Schaefer                                 Brass Lantern Enterprises
http://www.well.com/user/barts              http://www.brasslantern.com

Zsh: http://www.zsh.org | PHPerl Project: http://phperl.sourceforge.net   

Re: [4.0.2 bug] commands not written to history

[Vincent Lefevre]

On Sun, Jul 22, 2001 at 03:41:19 +0000, Bart Schaefer wrote:
> } because I ignore immediate dups:
> } 
> } Shell 1: true a
> } Shell 2: true b
> } Shell 1: true a
> } Shell 1: true c
> } 
> } Though after the last "true a", "true c" has been typed immediately
> } after it, the HISTFILE contains
> } 
> } true a
> } true b
> } true c
> } 
> } Is it possible to have immediate dups in the HISTFILE, but not in
> } the shell history?
> 
> Not for duplicates occurring in the same shell.  That is, you might get
> two `true a' in a row written out by different shells -- though they'd
> collapse to one when the $HISTFILE exceeded $SAVEHIST lines by a large
> enough margin to cause zsh to re-read/write it -- but in any given shell,
> the duplicate is thrown away before the check for unsaved commands is
> done.

What I wanted to say is: Could we have an option so that dups are
ignored in the shell history but not in $HISTFILE, so that we couldn't
have the above behaviour (useful when INC_APPEND_HISTORY is set)?

-- 
Vincent Lefèvre <vincent@vinc17.org> - Web: <http://www.vinc17.org/> - 100%
validated HTML - Acorn Risc PC, Yellow Pig 17, Championnat International des
Jeux Mathématiques et Logiques, TETRHEX, etc.
Work: CR INRIA - computer arithmetic / SPACES project at LORIA

Re: [4.0.2 bug] commands not written to history

[Vincent Lefevre]

The problem occurred again...

ay:~> ll .zhist-debug                                                 <15:31:12
total 544
-rw-------    1 lefevre  102         59115 Jul 22 02:39 complete.2328
-rw-------    1 lefevre  102         58977 Jul 22 01:42 complete.3943
-rw-------    1 lefevre  102         58975 Jul 22 01:43 complete.3975
-rw-------    1 lefevre  102         59162 Jul 22 15:31 complete.947
-rw-------    1 lefevre  102         59110 Jul 22 02:39 histfile.2328
-rw-------    1 lefevre  102         58973 Jul 22 01:42 histfile.3943
-rw-------    1 lefevre  102         58973 Jul 22 01:43 histfile.3975
-rw-------    1 lefevre  102         59115 Jul 22 15:31 histfile.947
-rw-r--r--    1 lefevre  102            30 Jul 22 15:31 startup.1449
-rw-r--r--    1 lefevre  102            30 Jul 22 01:19 startup.2328
-rw-r--r--    1 lefevre  102            30 Jul 22 01:35 startup.3943
-rw-r--r--    1 lefevre  102            30 Jul 22 01:35 startup.3975
-rw-r--r--    1 lefevre  102            30 Jul 22 12:31 startup.845
-rw-r--r--    1 lefevre  102            30 Jul 22 12:32 startup.947
-rw-r--r--    1 lefevre  102            30 Jul 22 12:32 startup.949
-rw-r--r--    1 lefevre  102            30 Jul 22 12:32 startup.951
-rw-------    1 lefevre  102             0 Jul 22 02:39 unsaved.2328
-rw-------    1 lefevre  102             0 Jul 22 01:42 unsaved.3943
-rw-------    1 lefevre  102             0 Jul 22 01:43 unsaved.3975

ay:~> cd .zhist-debug                                                 <15:34:43
ay:~/.zhist-debug> cat startup.2328                                   <15:34:49
Sun Jul 22 01:19:40 CEST 2001
ay:~/.zhist-debug> cat startup.947                                    <15:35:12
Sun Jul 22 12:32:02 CEST 2001

ay:~/.zhist-debug> tail -n 4 histfile.2328                            <15:36:18
: 995761695:0;cd
: 995761699:0;tail .tin/posted
: 995762334:0;tail -n 45 .tin/posted >| ~out/addposted
: 995762335:0;m ~out/addposted
ay:~/.zhist-debug> tail -n 4 complete.2328                            <15:36:25
: 995761695:0;cd
: 995761699:0;tail .tin/posted
: 995762334:0;tail -n 45 .tin/posted >| ~out/addposted
: 995762335:3;m ~out/addposted

In histfile.947:
: 995761695:0;cd
: 995761699:0;tail .tin/posted
: 995762334:0;tail -n 45 .tin/posted >| ~out/addposted
: 995797911:0;startx
: 995797938:0;ll .zhist-debug

In complete.947:
: 995761695:0;cd
: 995761699:0;tail .tin/posted
: 995762334:0;tail -n 45 .tin/posted >| ~out/addposted
: 995797911:0;startx
: 995798334:134;rpnews

-- 
Vincent Lefèvre <vincent@vinc17.org> - Web: <http://www.vinc17.org/> - 100%
validated HTML - Acorn Risc PC, Yellow Pig 17, Championnat International des
Jeux Mathématiques et Logiques, TETRHEX, etc.
Work: CR INRIA - computer arithmetic / SPACES project at LORIA

Re: [4.0.2 bug] commands not written to history

[Vincent Lefevre]

Sorry, a copy-paste problem:

ay:~> ll .zhist-debug                                                 <15:31:12
total 544
-rw-------    1 lefevre  102         59115 Jul 22 02:39 complete.2328
-rw-------    1 lefevre  102         58977 Jul 22 01:42 complete.3943
-rw-------    1 lefevre  102         58975 Jul 22 01:43 complete.3975
-rw-------    1 lefevre  102         59162 Jul 22 15:31 complete.947
-rw-------    1 lefevre  102         59110 Jul 22 02:39 histfile.2328
-rw-------    1 lefevre  102         58973 Jul 22 01:42 histfile.3943
-rw-------    1 lefevre  102         58973 Jul 22 01:43 histfile.3975
-rw-------    1 lefevre  102         59115 Jul 22 15:31 histfile.947
-rw-r--r--    1 lefevre  102            30 Jul 22 15:31 startup.1449
-rw-r--r--    1 lefevre  102            30 Jul 22 01:19 startup.2328
-rw-r--r--    1 lefevre  102            30 Jul 22 01:35 startup.3943
-rw-r--r--    1 lefevre  102            30 Jul 22 01:35 startup.3975
-rw-r--r--    1 lefevre  102            30 Jul 22 12:31 startup.845
-rw-r--r--    1 lefevre  102            30 Jul 22 12:32 startup.947
-rw-r--r--    1 lefevre  102            30 Jul 22 12:32 startup.949
-rw-r--r--    1 lefevre  102            30 Jul 22 12:32 startup.951
-rw-------    1 lefevre  102             0 Jul 22 02:39 unsaved.2328
-rw-------    1 lefevre  102             0 Jul 22 01:42 unsaved.3943
-rw-------    1 lefevre  102             0 Jul 22 01:43 unsaved.3975
-rw-------    1 lefevre  102             0 Jul 22 15:31 unsaved.947

-- 
Vincent Lefèvre <vincent@vinc17.org> - Web: <http://www.vinc17.org/> - 100%
validated HTML - Acorn Risc PC, Yellow Pig 17, Championnat International des
Jeux Mathématiques et Logiques, TETRHEX, etc.
Work: CR INRIA - computer arithmetic / SPACES project at LORIA

Re: [4.0.2 bug] commands not written to history

[Vincent Lefevre]

On Sat, Jul 21, 2001 at 18:32:20 +0000, Bart Schaefer wrote:
> Because zsh writes the history before calling TRAPEXIT, the `unsaved' file
> should always be empty.  If it is not, then INC_APPEND_HISTORY is causing
> an error when the history is written at exit time.

This isn't true here:

ay:~/.zhist-debug> cat unsaved.845                                    <17:29:25
: 995810482:0;
ay:~/.zhist-debug> tail -n 5 complete.845                             <17:29:39
: 995761699:0;tail .tin/posted
: 995762334:0;tail -n 45 .tin/posted >| ~out/addposted
: 995797911:12567;startx
: 995810481:1;halt
: 0:995797910;
ay:~/.zhist-debug> tail -n 5 histfile.845                             <17:29:48
: 995810431:0;ll ~out
: 995810450:0;cd out
: 995810455:0;zip -ru ../file.zip *
: 995810458:0;cd
: 995810467:0;tail -n 45 .tin/posted >| ~out/addposted

ay:~/.zhist-debug> cat unsaved.949                                    <17:31:36
: 995810477:0;
ay:~/.zhist-debug> tail -n 5 complete.949                             <17:31:39
: 995761695:0;cd
: 995761699:0;tail .tin/posted
: 995762334:0;tail -n 45 .tin/posted >| ~out/addposted
: 995797911:0;startx
: 0:995797922;
ay:~/.zhist-debug> tail -n 5 histfile.949                             <17:31:42
: 995810431:0;ll ~out
: 995810450:0;cd out
: 995810455:0;zip -ru ../file.zip *
: 995810458:0;cd
: 995810467:0;tail -n 45 .tin/posted >| ~out/addposted

-- 
Vincent Lefèvre <vincent@vinc17.org> - Web: <http://www.vinc17.org/> - 100%
validated HTML - Acorn Risc PC, Yellow Pig 17, Championnat International des
Jeux Mathématiques et Logiques, TETRHEX, etc.
Work: CR INRIA - computer arithmetic / SPACES project at LORIA