Evil Config Deck (ECD) bug: some config decks can prevent Multics from booting

[Gary Dixon]

GHM_Test crash created 2021-09-12 at 1014 investigates a problem found by dps8 developers in which some Multics configurations (config deck card combinations) can cause Multics bootload to crash.

The dump is available on the GHM system, as the 2nd in the list shown below.

CRASH: GHM_Test 2021-09-12 (dump copied to GHM)

azm:  list_dumps
Dumps in >dumps:
     030121.0630.0.7
     091221.1014.0.3

The config deck that produces the problem is shown below.

clok -delta 8. -zone pst
cpu -tag a -port 7 -state on -type dps8 -model 70. -cache 8.
mem -port a -size 4096. -state on
mem -port b -size 4096. -state on
mem -port c -size 4096. -state on
mem -port d -size 4096. -state on
iom -tag a -port 0 -model imu -state on
prph -device opca -iom a -chn 36 -model 6001. -ll 256. -state on
prph -subsys tapa -iom a -chn 12 -nchan 1 -model 8200. -number 16.
prph -subsys dska -iom a -chn 13 -nchan 1 -model 3381. -number 4.
prph -subsys dskb -iom a -chn 14 -nchan 1 -model 3381. -number 4.
prph -subsys dskc -iom a -chn 30 -nchan 1 -model 3381. -number 4.
prph -subsys dskd -iom a -chn 31 -nchan 1 -model 3381. -number 4.
prph -subsys dske -iom a -chn 32 -nchan 1 -model 3381. -number 4.
prph -subsys dskf -iom a -chn 33 -nchan 1 -model 3381. -number 4.
prph -subsys dskg -iom a -chn 34 -nchan 1 -model 3381. -number 4.
prph -subsys dskh -iom a -chn 35 -nchan 1 -model 3381. -number 4.
chnl -subsys dska -iom a -chn 37 -nchan 1
root -subsys dska -drive 00a -subsys dska -drive 00b -subsys dska -drive 00c
tcd -apt 1000. -itt 2000.
intk warm 0.
sst -4k 400. -16k 150. -64k 50. -256k 20.
part hc dska 00a
part dump dska 00a
parm loud

The crash is an "early bootload dump" meaning that many Multics subsystems have not been setup. For example, syserr logging is not established; so the azm syserr_log request does not provide data. However, log messages tracking progress of the bootload are sent to the operators console window if a "parm loud" config card is included.

The log messages captured on the GHM_Test console (by Eric Swenson) provide the following details.

 Messages from booting BCE...
  1721.4  initializer: 2009  scas_init  state 1  phase 2.
  1721.4  initializer: 2010  tc_init$early  state 1  phase 2.
  1721.4  initializer: 2011  init_sst$early  state 1  phase 2.
  1721.4  initializer: 2012  disabling slt allocation  state 1  phase 2.
  1721.4  initializer: 2013  initialize_faults$interrupt_init  state 1  phase 2.
  1721.4  initializer: 2016  load_disk_mpcs  state 1  phase 2.
  1721.4  initializer: 2017  init_pvt  state 1  phase 2.
  1721.4  initializer: 2018  read_disk$init  state 1  phase 2.
  1721.4  initializer: 2019  init_root_vols  state 1  phase 2.
  1721.4  initializer: 2020  establish_temp_segs  state 1  phase 2.
  1721.4  initializer: 2021  find_file_partition  state 1  phase 2.
  1721.4  initializer: 2025  load_mst$init_commands  state 1  phase 2.
  1721.4  initializer: 2028  scs_and_clock_init$date_time  state 1  phase 2.
  0921.4  initializer: 2029  io_config_init  state 1  phase 2.
  0921.4  initializer: 2030  ioi_init  state 1  phase 2.
  0921.4  initializer: 2031  init_toehold$save_safe_config_deck  state 1  phase 2.
  0921.4  initializer: 2032  bce_get_to_command_level  state 1  phase 2.
  bce (boot) 0921.4: M-> boot

 Messages from booting Multics...
  0921.5  initializer: 2033  establish_config_deck  state 1  phase 2.
  1721.5  initializer: 3009  scas_init  state 1  phase 3.
  1721.5  initializer: 3010  tc_init  state 1  phase 3.
  1721.5  initializer: 3011  init_sst$normal  state 1  phase 3.
  1721.7  initializer: 3012  disabling slt allocation  state 1  phase 3.
  1721.7  initializer: 3013  initialize_faults$interrupt_init  state 1  phase 3.
  1721.7  initializer: 3017  init_pvt  state 1  phase 3.
  1721.7  initializer: 3018  read_disk$init  state 1  phase 3.
  1721.7  initializer: 3019  init_root_vols  state 1  phase 3.
  1721.7  initializer: 3027  load_mst$make_permanent  state 1  phase 3.
  1721.7  initializer: 3028  scs_and_clock_init$date_time  state 1  phase 3.
  0921.7  initializer: 3029  io_config_init  state 1  phase 3.
  0921.7  initializer: 3030  ioi_init  state 1  phase 3.
  0921.7  initializer: 3031  init_toehold$save_safe_config_deck  state 1  phase 3.
  0921.7  initializer: 3033  establish_config_deck  state 1  phase 3.
  0921.7  initializer: 3034  init_partitions  state 1  phase 3.
  0921.7  initializer: 3035  make_segs_paged  state 1  phase 3.
  0921.7  initializer: 3036  collect_free_core  state 1  phase 3.
  0921.7  initializer: 3037  delete_segs$temp 1  state 1  phase 3.
 
 Crash message...
 CONSOLE: ALERT			
  0921.7  page_fault: fatal error at loc 2330
  0921.7  Multics not in operation; control process: Initializer.SysDaemon.z.

The machine conditions captured at time of dumping provide a pr6 (sp) value that can be used to trace the stack of the one process (Initializer.SysDaemon) running on the one CPU started at that early-bootload point (CPU a).

Machine conditions at time of dump (the RTB Machine Conditions above)
contain a stack pointer (PR6) that can provide a stack trace showing
sequence of calls leading to the crash.

azm:  mc -dump -long
Machine Conditions from Dump.

Bootload CPU Registers at Time of Dump:
Descriptor Segment Base Register: 175436500000 007770000000
Mode Register: 000000000061
Cache Mode Register: 000000000003
Pointer Registers:
   PR0 (ap) - 62|4456     inzr_stk0|4456
   PR1 (ab) - 25|246      bound_hc_data_wired$scs|246
   PR2 (bp) - 43|725      bound_priv_1$privileged_mode_ut|725
   PR3 (bb) - 4|0         fault_vector|0
   PR4 (lp) - 17|2340     ws_linkage|2340
   PR5 (lb) - 17|2340     ws_linkage|2340
   PR6 (sp) - 62|4400     inzr_stk0|4400
   PR7 (sb) - 62|0        inzr_stk0|0
Processor Registers:
   X0 - 3046 X1 - 4456 X2 - 0 X3 - 144
   X4 - 0 X5 - 3357 X6 - 2055 X7 - 120
   A Register - 025720657200 Q Register - 025773630200 E Register - 0
   Timer Register - 763242345 Ring Alarm Register - 0
Derail Fault (15)
SCU Data:
By: 43|370  bound_priv_1$privileged_mode_ut|370
Ref: 43|0  bound_priv_1$privileged_mode_ut|0
On: cpu a (#0)
Indicators:  cary, tro, ^bar
APU Status:  priv, sd-on, pt-on, fabs
Instructions:
    36    000000 0022 00      drl       0 interrupt inhibit
    37    000000 0022 00      drl       0 interrupt inhibit
Mem Controller Mask: 777774000010 000000000001
MC Fault Time: 00-12-31 17:00:00.0 pdt Mon  (000000000000000000)

Cannot set temporary pointers from the dump registers.

That stack trace is shown below.

azm:  stack 62|4400

Reverse trace of inzr_stk0 (Seg 62)
Number of stack frames 7.
Stack begin = 62|100 Stack end = 62|6360
FRAME       RETURN_PTR
62|4400     43|3046      bound_priv_1$syserr_real|1546
62|4120     42|5724      bound_page_control$page_error|34
62|3620     42|6213      bound_page_control$page_error|323
                    savex_stack at 62|3700, stack_size 15, valid 1
                       1577   bound_page_control$page_fault|1577
62|1040     42|13365     bound_page_control$pc|1417
62|700      31|10125     bound_active_1$delete_segs|213
62|220      431|1222     bound_init_1$real_initializer|1222
62|100      31|14        bound_active_1$initializer|14
Previous stack frame 77777|1

The immediate cause of the crash is a call by page_fault|2330 to page_error|page_fault_error, which emits the crashing syserr message, and causes a DRL fault triggering the dump. The three frames at top of the stack show these dump-triggering actions. But they provide few clues about how the bootload steps got to this point of failure.

Code in the page_control / page_fault / page_error subsystem generally do not push stack frames which switching from one subroutine to another. Instead all of the mini-subroutines share one large stack frame, and use TSXn instructions to transfer from one mini-subroutine (or quick procedure) to the next. So the stack trace does not show major actions taken within the page_control system that led to the crash.

Stack frames at the bottom of the trace show real_initializer performing steps of the bootload. Each step taken emits one of the syserr messages shown above, as a trace of progress during early bootload.

In particular, the call to delete_segs$temp reported just before the crash message corresponds to the stack frame at 62|700 in the stack trace. delete_segs is calling pc$truncate to remove one of the temporary segments associated with collection_1 of the boot process.

The call to pc$truncate (or page_control$truncate) passes an ASTe pointer as its first argument. Code from delete_segs shows setup for this call. The ASTE pointer is loaded from sp|106:

delete_segs|213 is line 90-91.  The if statement is false.
So pc$truncate is being called.

               if slte.abs_seg then call pc$cleanup (astep);

000167  aa  6 00112 3715 20   epp5      pr6|74,*            sltep
000170  aa  5 00001 2351 00   lda       pr5|1               slte.abs_seg
000171  aa   010000 3150 03   cana      4096,du
000172  aa   000010 6000 04   tze       8,ic                000202
000173  aa  6 00106 3521 00   epp2      pr6|70              astep
000174  aa  6 00132 2521 00   spri2     pr6|90
000175  aa  6 00130 6211 00   eax1      pr6|88
000176  aa   004000 4310 07   fld       2048,dl
000177  la  4 00010 3521 20   epp2      pr4|8,*             pc$cleanup
000200  aa  0 00623 7001 00   tsx0      pr0|403             call_ext_out
000201  aa   000012 7100 04   tra       10,ic               000213

                                                            STATEMENT 1 ON LINE 91
               else call pc$truncate (astep, 0);

000202  aa  6 00125 4501 00   stz       pr6|85
000203  aa  6 00106 3521 00   epp2      pr6|70              astep
000204  aa  6 00132 2521 00   spri2     pr6|90
000205  aa  6 00125 3521 00   epp2      pr6|85
000206  aa  6 00134 2521 00   spri2     pr6|92
000207  aa  6 00130 6211 00   eax1      pr6|88
000210  aa   010000 4310 07   fld       4096,dl
000211  la  4 00012 3521 20   epp2      pr4|10,*            pc$truncate
000212  aa  0 00623 7001 00   tsx0      pr0|403             call_ext_out

A display of that ASTe entry shows the following data:

azm:  set sp 62|700

azm:  d sp|106,* -as aste
aste                          @ 102|16354
  fp = "016354"b3, bp = "016354"b3, infl = "000000"b3, infp = "000000"b3,
  strp = "000436"b3, par_astep = "000000"b3,
  uid = "000000000000"b3, msl = "000"b3, pvtx = 1, vtocx = -1,
  dtu = "000000000000"b3, dtm = "000000000000"b3, quota (0) = 0,
  quota (1) = 9, used (0) and used (1) = 0, csl = "011"b3,
  records = "011"b3, np = "011"b3, ht_fp = "000000"b3, ptsi = "01"b,
  marker = "02"b3
  ON:  usedf, hc_sdw, hc_part, ehs, nqsw, fmchanged, dnzp
  OFF: init, gtus, gtms, hc, any_access_on, write_access_on, inhibit_cache,
       explicit_deact_ok, deact_error, fm_damaged, multi_class,
       dius, nid, dmpr_pad, dirsw, master_dir, volmap_seg,
       tqsw (0) and tqsw (1), fms, npfs, gtpd, per_process, ddnp, fmchanged1,
       damaged, pack_ovfl, synchronized

Notice that the segno associated with this ASTe is given in aste.strp: 436 (octal)

azm:  sdw 436
 ADDRESS RNGS  CA-MAX REWPUGCDF EBOUND SEGNO SEGMENT-NAME
       0  000      17                0   436 free_area_1

Notice also an important clue. The aste.fp and aste.bp offsets are aqual to the offset of this ASTe, meaning that the ASTe is in a threaded list (otherwise these offsets would be "000000"b3 if it was not threaded in a list). But the next ASTe in the list points to this ASTe; the ASTe is threaded to itself.

This represents an infinite loop situation which could cause several calls to pc$truncate for the same ASTe. However, it is unclear whether attempting to truncate an entry more than once would result in the immediate failure which triggered the crash; this immediate failure has not been described as yet. But the infinite loop is definitely an issue underlying the crash.

More details will be added to this ticket as further dump analysis and experimentation continue.