CAC 2016-07-25

fnp wtx tally wrong

tally address 01005170^M
tally 124^M
 015012000000^M

DBG(152734860)> CPU0 TRACE: 00122:004560 bound_355_wired:dn355+04560^M
DBG(152734860)> CPU0 TRACE:       874             dcw_list (j).dcw_tally = bit (buffer.tally, 9);^M
DBG(152734860)> CPU0 TRACE: 00122:004560 0 500000551104 (STBA PR5|0,IC) 500000 551(0) 1 0 0 04^M
DBG(152734860)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01005170  readData=205573000000^M
DBG(152734860)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=01005170 writeData=205573000174^M

DBG(152734844)> CPU0 TRACE: 00122:004550 bound_355_wired:dn355+04550^M
DBG(152734844)> CPU0 TRACE:       874             dcw_list (j).dcw_tally = bit (buffer.tally, 9);^M
DBG(152734844)> CPU0 TRACE: 00122:004550 0 600274236120 (LDQ PR6|274,N*) 600274 236(0) 1 0 1 00^M
DBG(152734844)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70360454  readData=000223000043^M
DBG(152734844)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70360455  readData=005572000000^M
DBG(152734844)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01007572  readData=005632001174^M

is 0174 in buffer.tally -- backtrace 01007572

002114  aa  5 00000 5521 04   stbq      pr5|0,04            buffer.tally^M
WATCH [152731914] write  01007572 000000001174 (Write)^M

DBG(152731914)> CPU0 DBG: 00147:004716 bound_tty_active:tty_write+02114^M
002114  aa  5 00000 5521 04   stbq      pr5|0,04            buffer.tally^M
DBG(152731914)> CPU0 DBG: 00147:004716 0 500000552104 (STBQ PR5|0,IC) 500000 552(0) 1 0 0 04^M
DBG(152731914)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01007572  readData=000000001000^M
 Q=000000000174

                                                            STATEMENT 1 ON LINE 845
                              lastp -> buffer.tally = old_char_count + nchars;

002112  aa  7 00253 0761 00   adq       pr7|171             old_char_count
002113  aa  7 00226 3715 20   epp5      pr7|150,*           buffer.tally
002114  aa  5 00000 5521 04   stbq      pr5|0,04            buffer.tally

DBG(152540246)> CPU0 TRACE: 00147:004713 bound_tty_active:tty_write+02111^M
DBG(152540246)> CPU0 TRACE: 002111  aa  7 00254 7561 00     stq       pr7|172             nchars^M
DBG(152540246)> CPU0 TRACE: 00147:004713 0 700254756100 (STQ PR7|254) 700254 756(0) 1 0 0 00^M
DBG(152540246)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=70364474 writeData=000000000174^M

DBG(152540244)> CPU0 TRACE: 00147:004712 bound_tty_active:tty_write+02110^M
DBG(152540244)> CPU0 TRACE: 002110  aa  7 00251 2361 00     ldq       pr7|169             chars_in_buf^M
DBG(152540244)> CPU0 TRACE: 00147:004712 0 700251236100 (LDQ PR7|251) 700251 236(0) 1 0 0 00^M
DBG(152540244)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70364471  readData=000000000174^M
DBG(152540244)> CPU0 REGDUMPAQI: A=777777007777 Q=000000000174 IR:~BAR Tally Carry ^M
DBG(152540244)> CPU0 REGDUMPFLT: E=000 A=777777007777 Q=000000000174 -7.510214346e-06^M

DBG(152540188)> CPU0 TRACE: 00147:004651 bound_tty_active:tty_write+02047^M
DBG(152540188)> CPU0 TRACE: 002047  aa  7 00251 7561 00     stq       pr7|169             chars_in_buf^M
DBG(152540188)> CPU0 TRACE: 00147:004651 0 700251756100 (STQ PR7|251) 700251 756(0) 1 0 0 00^M
DBG(152540188)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=70364471 writeData=000000000174^M

                                                            STATEMENT 1 ON LINE 821
                                   chars_in_buf = 4 * (words_needed - 1) - wtcb.buffer_pad;

Actually, this isn't the interesting case; the trail nulls may be legitimate padding.

Reset; Track down the short writes....

tally address 01006072
tally 31

DBG(156923148)> CPU0 DBG: 00122:004560 bound_355_wired:dn355+04560^M
      874                     dcw_list (j).dcw_tally = bit (buffer.tally, 9);^M
DBG(156923148)> CPU0 DBG: 00122:004560 0 500000551104 (STBA PR5|0,IC) 500000 551(0) 1 0 0 04^M
WATCH [156923148] write  01006072 211313000037 (Write)^M

DBG(156923132)> CPU0 TRACE: 00122:004550 bound_355_wired:dn355+04550^M
DBG(156923132)> CPU0 TRACE:       874             dcw_list (j).dcw_tally = bit (buffer.tally, 9);^M
DBG(156923132)> CPU0 TRACE: 00122:004550 0 600274236120 (LDQ PR6|274,N*) 600274 236(0) 1 0 1 00^M
DBG(156923132)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70320614  readData=000223000043^M
DBG(156923132)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70320615  readData=011312000000^M
DBG(156923132)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01013312  readData=000000000037^M

watch 01013312

DBG(157848439)> CPU0 DBG: 00147:004716 bound_tty_active:tty_write+02114^M
002114  aa  5 00000 5521 04   stbq      pr5|0,04            buffer.tally^M
DBG(157848439)> CPU0 DBG: 00147:004716 0 500000552104 (STBQ PR5|0,IC) 500000 552(0) 1 0 0 04^M
WATCH [157848439] write  01013312 000000000037 (Write)^M

DBG(157848427)> CPU0 TRACE: 00147:004707 bound_tty_active:tty_write+02105^M
DBG(157848427)> CPU0 TRACE: 002105  aa  7 00205 2361 00     ldq       pr7|133             break_length^M
DBG(157848427)> CPU0 TRACE: 00147:004707 0 700205236100 (LDQ PR7|205) 700205 236(0) 1 0 0 00^M
DBG(157848427)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70324425  readData=000000000037^M

DBG(157848429)> CPU0 TRACE: 00147:004710 bound_tty_active:tty_write+02106^M
DBG(157848429)> CPU0 TRACE: 002106  aa  7 00251 1161 00     cmpq      pr7|169             chars_in_buf^M
DBG(157848429)> CPU0 TRACE: 00147:004710 0 700251116100 (CMPQ PR7|251) 700251 116(0) 1 0 0 00^M
DBG(157848429)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70324471  readData=000000000074^M

So the buffer length is being clipped to break_length, which explains where the short tally came from, but not where break_length came from.

  dcl  break_length fixed bin;   /* no. of characters before end-of-page */

 break_length = index (final_outp -> output_chars, eop_sentinel) - 1;
                                              /* look for page break */

  dcl  eop_sentinel_octal fixed bin (9) unsigned int static init (011111111b) options (constant);
        /* i.e., 377(8) */
  dcl  eop_sentinel char (1);
  op_sentinel = byte (eop_sentinel_octal);

No particular reason to expect a 377 in the output string....

                         break_length = index (final_outp -> output_chars, eop_sentinel) - 1;

001402  aa  7 00134 3535 20   epp3      pr7|92,*            final_outp
001403  aa  000 100 124 540   scm       (pr,rl),(pr),mask(000)
001404  aa  3 00000 00 0006   desc9a    pr3|0,ql            output_chars
001405  aa  7 00310 00 0001   desc9a    pr7|200,1           eop_sentinel
001406  aa  6 00056 0001 00   arg       pr6|46
001407  aa  6 00056 2361 00   ldq       pr6|46
001410  aa   000002 6070 04   ttf       2,ic                001412
001411  aa   000001 3360 07   lcq       1,dl
001412  aa  7 00205 7561 00   stq       pr7|133             break_length

Hmmm. SCM....

DBG(157841799)> CPU0 TRACE: 001412  aa  7 00205 7561 00     stq       pr7|133             break_length
DBG(157841799)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=70324425 writeData=777777777777

No; that's correct, SCM said it wasn't found///

                              break_length = output_length;

DBG(157841807)> CPU0 TRACE: 001416  aa  7 00205 7561 00     stq       pr7|133             break_length
DBG(157841807)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=70324425 writeData=000000000372

tty_write breaks the output into a chain of buffers; I believe the idea is that the FNP is such a resource-constrained system that it does not have the memory to handle large buffers, so the output is broken into a "buffer chain" and a channel command program is constructed that passes a list of buffers to the FNP; the FNP walks the channel command program, picking up each each buffer and sending it down the wire and then moving on to the next buffer.

tty_write is breaking the login banner into a buffer chain, and passes the chain (eventually) to dn355$process_send_output, which walks the chain, constructing the channel command program. It picks up the first buffer and adds to the program, but

      877   pcb.write_first = buffer.next;    /* now bump to next buffer */
DBG(156923154)> CPU0 TRACE: 00122:004563 0 600274235120 (LDA PR6|274,N*) 600274 235(0) 1 0 1 00
DBG(156923154)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01013312  readData=000000000037

(buffer.next is in the high half-word)  indicates that there is only one buffer in the chain; so the FNP never sees the rest of the banner.

Now backtracking the history of buffer.next....

      896                buffer.next = 0;                             /* indicate end of active write block */

Buffer.next is set to NULL because the loop terminated early?

Looking at the loop:

First time 

DBG(156923062)> CPU0 TRACE:       866        do j = 1 to max_chain_len while (pcb.write_first ^= 0 & output_chars < output_limit & continue);

DBG(156923062)> CPU0 TRACE: 00122:004457 0 000020236007 (LDQ 000020,DL) 000020 236(0) 0 0 0 07
DBG(156923064)> CPU0 TRACE: 00122:004460 0 600355756100 (STQ PR6|355) 600355 756(0) 1 0 0 00

Set loop limit to max_chain_length

DBG(156923066)> CPU0 TRACE: 00122:004461 0 000001236007 (LDQ 000001,DL) 000001 236(0) 0 0 0 07
DBG(156923068)> CPU0 TRACE: 00122:004462 0 600132756100 (STQ PR6|132) 600132 756(0) 1 0 0 00

Presumably J

DBG(156923072)> CPU0 TRACE: 00122:004464 0 600132236100 (LDQ PR6|132) 600132 236(0) 1 0 0 00
DBG(156923074)> CPU0 TRACE: 00122:004465 0 600355116100 (CMPQ PR6|355) 600355 116(0) 1 0 0 00
DBG(156923076)> CPU0 TRACE: 00122:004466 0 000117605404 (TPNZ 000117,IC) 000117 605(1) 0 0 0 04

J <= max_chain_length?

DBG(156923078)> CPU0 TRACE: 00122:004467 0 600270373520 (EPP7 PR6|270,N*) 600270 373(1) 1 0 1 00
DBG(156923080)> CPU0 TRACE: 00122:004470 0 700001235100 (LDA PR7|1) 700001 235(0) 1 0 0 00
DBG(156923082)> CPU0 TRACE: 00122:004471 0 000066733000 (LRS 000066) 000066 733(0) 0 0 0 00
DBG(156923084)> CPU0 TRACE: 00122:004472 0 000113600004 (TZE 000113,IC) 000113 600(0) 0 0 0 04
DBG(156923086)> CPU0 TRACE: 00122:004473 0 601102756100 (STQ PR6|1102) 601102 756(0) 1 0 0 00

pcb.write_first ^= 0

DBG(156923088)> CPU0 TRACE: 00122:004474 0 600151236100 (LDQ PR6|151) 600151 236(0) 1 0 0 00
DBG(156923088)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70320471  readData=000000000000
DBG(156923090)> CPU0 TRACE: 00122:004475 0 600150116100 (CMPQ PR6|150) 600150 116(0) 1 0 0 00
DBG(156923090)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70320470  readData=000000003700
DBG(156923092)> CPU0 TRACE: 00122:004476 0 000107605004 (TPL 000107,IC) 000107 605(0) 0 0 0 04

output_chars < output_limit

DBG(156923094)> CPU0 TRACE: 00122:004477 0 600162235100 (LDA PR6|162) 600162 235(0) 1 0 0 00
DBG(156923094)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=70320502  readData=400000000000
DBG(156923096)> CPU0 TRACE: 00122:004500 0 000105600004 (TZE 000105,IC) 000105 600(0) 0 0 0 04

continue?

DBG(156923098)> CPU0 TRACE:       868             dcw_list (j).dcw_ptr = bit (bin (pcb.write_first + dataoff + tty_buf.absorig, 18), 18);
DBG(156923116)> CPU0 TRACE: 00122:004514 0 100000551160 (STBA PR1|0,*N) 100000 551(0) 1 0 3 00
dcw_list (0).dcw_ptr = 211313

DBG(156923124)> CPU0 TRACE:       870             blockp = ptr (ttybp, pcb.write_first);  /* get ptr to buffer */
DBG(156923124)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=70320615 writeData=011312000000

DBG(156923126)> CPU0 TRACE:       871             if buffer.tally = 0                     /* we don't want this in a dcw */
DBG(156923126)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01013312  readData=000000000037
DBG(156923132)> CPU0 TRACE:       874             dcw_list (j).dcw_tally = bit (buffer.tally, 9);

DBG(156923148)> CPU0 TRACE: 00122:004560 0 500000551104 (STBA PR5|0,IC) 500000 551(0) 1 0 0 04
DBG(156923148)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=01006072 writeData=211313000037

DBG(156923150)> CPU0 TRACE:       876             dcw_list (j).pad = "0"b;                /* 355 depends on this */
DBG(156923152)> CPU0 APPENDING: Write(Actual) Write: iefpFinalAddress=01006072 writeData=211313000037

DBG(DBG(156923154)> CPU0 TRACE: 00122:004563 0 600274235120 (LDA PR6|274,N*) 600274 235(0) 1 0 1 00
156923154)> CPU0 TRACE:       877             pcb.write_first = buffer.next;          /* now bump to next buffer */
DBG(156923154)> CPU0 APPENDING: Read (Actual) Read:  iefpFinalAddress=01013312  readData=000000000037

Already broken...

Back track from here... Problem seems to be back in tty_write....

      930                          lastp -> buffer.next = 0;          /* break the chain at page end */
Unless otherwise stated, the content of this page is licensed under Creative Commons Attribution-ShareAlike 3.0 License