Build times out waiting for string #640

larsbrinkhoff · 2018-06-16T19:23:22Z

It always seems to die for me in the same place, waiting on the string EINIT even though it's right there.

Steps to reproduce:

git clone https://github.com/PDP-10/its.git
cd its
git submodule init
git submodule update
make EMULATOR=klh10

I also tried building with simh. It still dies as the same place waiting for EINIT.

36bit · 2018-01-26T19:28:02Z

I should also say this is with Ubuntu 17.10 (Artful Aardvark.)
Lars mentioned in the IRC channel that it worked for him on 14.04 and 16.04 although I could not duplicate that success on 14.04.

aap · 2018-01-26T20:15:59Z

There is a timeout defined in build.tcl (set timeout 100). I had to increase it when i built on a raspi once.

36bit · 2018-01-26T22:39:30Z

Thanks. I added an extra 0 to that, setting the timeout to 1000. The outcome was the same although it took longer to get there.

I also tried replacing expect "EINIT" with sleep 75 to see if that might get beyond this stage but it still timed out.

I also tried setting it to expect "IT IS NOW" in case it's looking just at the last line but that, too, did not make a difference. It still times out.

larsbrinkhoff · 2018-01-26T22:48:47Z

I think we need some expect/TCL debugging to see what's really going on. I don't have such expertise myself.

larsbrinkhoff · 2018-01-26T22:51:05Z

https://wiki.tcl.tk/3173 suggests to invoke expect with -d.

Other hints are to use log_file, log_user, and exp_internal.

Some more here: http://wiki.tcl.tk/473#pagetoce1b59b05

36bit · 2018-01-26T23:17:35Z

Oh yes, that was helpful. Doing using -d shows that it is not hanging over EINIT as originally thought but it's waiting for the next thing in build.tcl. It is timing out waiting for :EJ which never appears.

expect: does " >\r\nIT IS NOW 3:09:15 PM EST, FRIDAY, JAN 26,20" (spawn_id exp10) match exact string ":EJ"? no
expect: timed out

The last command timed out.
make: *** [out/rp0.dsk] Error 1
Makefile:31: recipe for target 'out/rp0.dsk' failed

larsbrinkhoff · 2018-01-26T23:28:27Z

In that case, I wonder why your build doesn't generate the -> DSK messages. This is what it looks like when I build:

Compressing file DSK: EMACS1; BUFFER >
Compressing file DSK: EMACS1; CRL >
Compressing file DSK: EMACS1; VARS >
 -> DSK: EMACS; [PURE] >
Compressing file DSK: EMACS1; PURIFY >
Compressing file DSK: EMACS1; CCL >
 -> DSK: EMACS; [PRFY] >
Compressing file DSK: EMACS1; EINIT >
 -> DSK: EMACS; EINIT ^Q:EJ

larsbrinkhoff · 2018-01-26T23:29:47Z

Maybe we can look for > instead of :EJ.

larsbrinkhoff · 2018-02-01T18:01:33Z

Hello @36bit,

I have made a branch called lars/colon-ej. Can you test it and see if you get past this section of the build script?

Maybe it'll grind to a halt further on, but let's try this first.

36bit · 2018-02-02T19:42:59Z

It does indeed seem to get further:

*:kill
*:link sys3;ts teco,.teco.;tecpur >
*
DB     HACTRN SYS3   TS     TECO   LINK   11:27:46
:link sys2;ts emacs,emacs;ts >
*
DB     HACTRN SYS2   TS     EMACS  LINK   11:27:47
:emacs


EMACS Editor, version 162 - type Help(^_H) for help.


M-X run Library$einit$? Generate
Compressing file DSK: EMACS1; DOC >
Compressing file DSK: EMACS1; USRCOM >
Compressing file DSK: EMACS1; ^RBASE >
Compressing file DSK: EMACS1; WRDLST >
Compressing file DSK: EMACS1; INDENT >
Compressing file DSK: EMACS1; SEARCH >
Compressing file DSK: EMACS1; FILES >
Compressing file DSK: EMACS1; SUPPRT >
Compressing file DSK: EMACS1; ISEARC >
Compressing file DSK: EMACS1; WINDOW >
Compressing file DSK: EMACS1; BUFFER >
Compressing file DSK: EMACS1; CRL >
Compressing file DSK: EMACS1; VARS >
Compressing file DSK: EMACS1; PURIFY >
Compressing file DSK: EMACS1; CCL >
Compressing file DSK: EMACS1; EINIT >


M-X generate Library$emacs;aux$emacs1;aux
Compressing file DSK: EMACS1; AUX >
 -> DSK: EMACS; AUX ^Q:EJ

*:kill
*:delete emacs;ts 126
*:delete [prfy] <
*:delete [pure] 162
*:rename [pure] 163, [pure
IT IS NOW 11:27:55 AM EST, FRIDAY, FEB 2,2018
] 162
DSK: EMACS; [PURE] 163 - FILE NOT FOUND

The last command timed out.
Makefile:31: recipe for target 'out/rp0.dsk' failed

From doing the build with the debug switch:

expect: does "ND
IDAY, FEB 2,2018\r\ne] 162\r\nDSK: EMACS; [PURE] 163 - FILE NOT FOUND\r\n" (spawn_id exp10) match exact string "*"? no
expect: timed out

larsbrinkhoff · 2018-02-02T20:17:35Z

Thanks. Bad luck there, the "ITS IS NOW..." message interrupts the :rename command.

Does this happen consistently at this point?

36bit · 2018-02-02T22:52:30Z

Does this happen consistently at this point?

It does seem to. I've tried it 4 times and it seems to vary: It might chop [pure and the closing ] onto a separate line or maybe [pure] will be fine and the 162 will go onto a new line.

larsbrinkhoff · 2018-02-03T09:52:42Z

@eswenson1 saw something similar when trying to build in macOS.

larsbrinkhoff · 2018-02-24T08:02:38Z

I think the -> ... :EJ message comes from CCL. Could be a problem with timestamps?

    0[5                             !* If there's an old pure file more recent than!
    1:< er^]2^[ fs if cdate^[u5 ec>   !* all COMPRS files, no need to purify.!
    Q5"n q5-q4"g 0^\''

    FT_->_^]2                       !* Otherwise, we must purify, so tell user.!

larsbrinkhoff · 2018-02-24T16:15:51Z

I was experimenting with generating library files from EMACS. There was no -> message, and also there was no new :EJ file written out. Turns out the ITS clock was not set. After running :PDSET, the message appeared and the file was written.

So if there is no ->, there really is a problem. Expecting some other string only masks the problem.

I will now check if the clock is set correctly on every boot.

larsbrinkhoff · 2018-02-24T18:51:36Z

The clock is not set correctly when running in SIMH after a call to maybe_pdset in build.tcl.

larsbrinkhoff · 2018-02-25T18:11:49Z

Hello @36bit,

Can you try the lars/pdset branch?

36bit · 2018-02-26T00:42:25Z

*:load sysbin;teco bin  
*dumpit$g'TECO$:
$Y $
DSK: SYSBIN; TECO BIN   
DB     HACTRN SYSBIN _DUMP_ OUTPUT WRITE  16:30:01
DB     HACTRN SYSBIN TECO   BIN    DELRNM 16:30:01
*Purified
:PDUMP$
DSK: .TECO.; TECPUR 1212
*:kill
*:link sys3;ts teco,.teco.;tecpur >
*
DB     HACTRN SYS3   TS     TECO   LINK   16:30:05
:link sys2;ts emacs,emacs;ts >
*
DB     HACTRN SYS2   TS     EMACS  LINK   16:30:07
:emacs


EMACS Editor, version 162 - type Help(^_H) for help.


M-X run Library$einit$? Generate
Compressing file DSK: EMACS1; DOC >
Compressing file DSK: EMACS1; USRCOM >
Compressing file DSK: EMACS1; ^RBASE >
Compressing file DSK: EMACS1; WRDLST >
Compressing file DSK: EMACS1; INDENT >
Compressing file DSK: EMACS1; SEARCH >
Compressing file DSK: EMACS1; FILES >
Compressing file DSK: EMACS1; SUPPRT >
Compressing file DSK: EMACS1; ISEARC >
Compressing file DSK: EMACS1; WINDOW >
Compressing file DSK: EMACS1; BUFFER >
Compressing file DSK: EMACS1; CRL >
Compressing file DSK: EMACS1; VARS >
Compressing file DSK: EMACS1; PURIFY >
Compressing file DSK: EMACS1; CCL >
Compressing file DSK: EMACS1; EINIT >

The last command timed out.
Makefile:32: recipe for target 'out/rp0.dsk' failed
make: *** [out/rp0.dsk] Error 1

36bit · 2018-02-26T00:43:14Z

The process was the same except for checking out the branch:

git clone https://github.com/PDP-10/its.git
cd its
git checkout lars/pdset
git submodule init
git submodule update
make EMULATOR=klh10

larsbrinkhoff · 2018-02-26T05:46:42Z

Thanks for testing!

larsbrinkhoff · 2018-02-26T11:34:35Z

Can you check timestamps of :EJ and COMPRS files? I.e. log in and list the EMACS and EMACS1 directories.

larsbrinkhoff · 2018-06-15T16:47:22Z

I have now run into this myself, so I had a chance to examine the state of the system more closely.

It seems files written by DUMP have timestamps a few hours later than what the system clock is set to. This wrecks havoc with EMACS compression. It only compresses files when needed, i.e. the source files are old. In this case it looks to EMACS as if they are new.

larsbrinkhoff · 2018-06-16T15:24:49Z

I'm checking a successful build and see that the EMACS1 file timestamps are weeks old. They match the files from the Unix host.

I'm rerunning a build on my machine with timestamps updated to "right now".

Maybe a fix would be to set back all timestamps in the src/emacs1 directory.

larsbrinkhoff · 2018-06-16T15:29:22Z

Still works on my machine, but I see the timestamps in ITS are six hours before those in Unix.

larsbrinkhoff · 2018-06-16T16:35:29Z

Setting back the timestamps two days seems to be a workaround on the previously failing build host.

larsbrinkhoff · 2018-06-16T19:24:31Z

@36bit, can you test this?

larsbrinkhoff · 2018-06-18T10:03:13Z

This "24 hours ago" workaround didn't work for me on a fresh repository. So apparently it's something about checking out new files with git, and then starting a build.

I'll check in more detail what's going on with the timestamps.

What are the Unix atime, ctime, mtime timestamps?
Which one(s) is itstar picking up and putting in the tape image?
What is DUMP reading off the tape?
What are the ITS creation and reference timestamps?

larsbrinkhoff · 2018-06-18T12:00:28Z

I was touching the filestamps of the wrong files. It's not the source files in EMACS1, but the purified files in EMACS.

larsbrinkhoff · 2018-06-18T13:45:36Z

I tested this a few times by checkout out a fresh repository and building. It should work now.

eswenson1

This is gross!

atsampson · 2018-06-18T16:21:13Z

Makefile

@@ -66,6 +66,8 @@ $(OUT)/ka-minsys.tape: $(ITSTAR)
 $(OUT)/sources.tape: $(ITSTAR) build/$(EMULATOR)/stamp $(OUT)/syshst/$(H3TEXT)
 	mkdir -p $(OUT)
 	rm -f src/*/*~
+	touch -d "24 hours ago" bin/emacs/einit.*


That kind of -d is a GNU extension - it won't work with (e.g.) FreeBSD's touch.

$ touch -d "24 hours ago" foo
touch: out of range or illegal time specification: YYYY-MM-DDThh:mm:SS[.frac][tz]

larsbrinkhoff · 2018-06-18T18:46:10Z

Ok, instead of a gross hack which doesn't work on FreeBSD, I'll use the actual original filestamps for those three files.

Build times out waiting for string #640

Build times out waiting for string #640

Conversation

larsbrinkhoff commented Jun 16, 2018

36bit commented Jan 26, 2018

aap commented Jan 26, 2018

36bit commented Jan 26, 2018

larsbrinkhoff commented Jan 26, 2018

larsbrinkhoff commented Jan 26, 2018 • edited Loading

36bit commented Jan 26, 2018

larsbrinkhoff commented Jan 26, 2018

larsbrinkhoff commented Jan 26, 2018

larsbrinkhoff commented Feb 1, 2018

36bit commented Feb 2, 2018

larsbrinkhoff commented Feb 2, 2018

36bit commented Feb 2, 2018 • edited Loading

larsbrinkhoff commented Feb 3, 2018

larsbrinkhoff commented Feb 24, 2018

larsbrinkhoff commented Feb 24, 2018 • edited Loading

larsbrinkhoff commented Feb 24, 2018

larsbrinkhoff commented Feb 25, 2018

36bit commented Feb 26, 2018

36bit commented Feb 26, 2018

larsbrinkhoff commented Feb 26, 2018

larsbrinkhoff commented Feb 26, 2018

larsbrinkhoff commented Jun 15, 2018 • edited Loading

larsbrinkhoff commented Jun 16, 2018

larsbrinkhoff commented Jun 16, 2018

larsbrinkhoff commented Jun 16, 2018

larsbrinkhoff commented Jun 16, 2018

larsbrinkhoff commented Jun 18, 2018 • edited Loading

larsbrinkhoff commented Jun 18, 2018

larsbrinkhoff commented Jun 18, 2018

eswenson1 left a comment

Choose a reason for hiding this comment

atsampson Jun 18, 2018

Choose a reason for hiding this comment

larsbrinkhoff commented Jun 18, 2018

larsbrinkhoff commented Jun 18, 2018

larsbrinkhoff commented Jun 19, 2018

atsampson commented Jun 19, 2018

larsbrinkhoff commented Jan 26, 2018 •

edited

Loading

36bit commented Feb 2, 2018 •

edited

Loading

larsbrinkhoff commented Feb 24, 2018 •

edited

Loading

larsbrinkhoff commented Jun 15, 2018 •

edited

Loading

larsbrinkhoff commented Jun 18, 2018 •

edited

Loading