socket_select crash

Part of my rather complex system (written in BASIC) crashes in very specific circumstances. The function concerned has been called many times before the crash, and it crashes while calling an SWI, Socket_Select.

It’s been pointed out that within the disassembly around the crash address, R0 is not word aligned. I have no way to find out what causes this, as all the parameters I pass to the SWi are word aligned.

The calling line is the FNselect below:

IF DEBUG%AND2048 THEN *report SCL: caller$: before FD_SETSIZE% ~readmask% ~writemask% ~!readmask% ~!writemask% ~!(readmask%4) ~!(writemask%4) broadcast_s% server_s% poll_delay%
events%=FNselect(FD_SETSIZE%, readmask%, writemask%, NULL%, poll_delay%)
IF DEBUG%AND16384 THEN
*report SCL: caller$: after events% ~!readmask% ~!writemask% ~!(readmask%4) ~!(writemask%4)
A$= FNSL_serror
IF DEBUG%AND2048 THEN *report SCL: caller$: events% A$ ~!readmask% ~!writemask%
ENDIF

The called function is:

DEF FNselect(ndfs%, readfds%, writefds%, exceptfds%, timeval%)
LOCAL R%,V%
errno%=0
SYS “XSocket_Select”,ndfs%,readfds%,writefds%,exceptfds%,timeval% TO R%;V%
IF=Vflag% THEN errno%=!R%:R%=SOCKET_ERROR%
IF errno%>error_base% THEN errno%-=error_base%
=R%

The crash occurs while executing the SYS call above:

The debug output is:

Trace @ 594
SCL: caller$=“ServerLog”: before FD_SETSIZE%=128 ~readmask%=&859E0 ~writemask%=&85A08 ~!readmask%=&8000 ~!writemask%=&8000 ~!(readmask%4)=&0 ~!(writemask%4)=&0 broadcast_s%=12 server_s%=15 poll_delay%=547264
Trace @ 595
Trace @ 416
Trace @ 417
14:42:05.53 * Error *
Error : &80000002
Message: Internal error: abort on data transfer at &FC19D288
Trace @ 12

Reporter shows the following at a WHERE command:

Memory: Prog=14,113 Vars=328,360 Free=124,208 Stack=516 Undefined=0 Slot=460K
Address &FC19D288 in Module BASIC @ &FC199F4C + &333C
Register dump (at &20011C30) is:
pc = &FC19D288 Flags=&00000110=nzcv if Mode=User 32 bit
r0 = &3A494D25 : MI: : 977882405
r1 = &3A494D25 : %MI: : 977882405
r2 = &00000067 : g… : 103
r3 = &00000075 : u… : 117
r4 = &0005A166 : f¡.. : 368998
r5 = &25004553 : SE. : 620774739
r6 = &0005A16B : k¡.. : 369003
r7 = &FC1A3240 : @2.ü : 4229575232
r8 = &00008700 : .‡.. : 34560
r9 = &00000005 : …. : 5
r10 = &00000072 : r… : 114
r11 = &0005A16B : k¡.. : 369003
r12 = &0005A14F : O¡.. : 368975
r13 = &0013CF68 : hÏ.. : 1298280
r14 = &FC1A32DC : Ü2.ü : 4229575388
Code around address is:
FC19D250 : Invalid address

Reporter 2.71s (21 Nov 2018) Listed 17180 lines

disassembly of the area shows:

FC19D260 : .04à : E034300B : EORS R3,R4,R11
FC19D264 : 0… : 0A000030 : BEQ &FC19D32C
FC19D268 : .0Ôä : E4D43001 : LDRB R3,[R4],#1
FC19D26C : [.Zã : E35A005B : CMP R10,#&5B ; =“[”
FC19D270 : .S3 : 33530025 : CMPCC R3,#&25 ; =""
FC19D274 : <… : 0A00003C : BEQ &FC19D36C
FC19D278 : ..°á : E1B00001 : MOVS R0,R1
FC19D27C : C… : 0A000043 : BEQ &FC19D390
FC19D280 : ".°è : E8B00022 : LDMIA R0!,{R1,R5}
FC19D284 : eT á : E1A05465 : MOV R5,R5,ROR #8
FC19D288 : %.3á : E1330C25 : TEQ R3,R5,LSR #24
FC19D28C : ùÿÿ. : 1AFFFFF9 : BNE &FC19D278
FC19D290 : ..4á : E134000B : TEQ R4,R11
FC19D294 : …. : 0A00001C : BEQ &FC19D30C
FC19D298 : .` á : E1A06004 : MOV R6,R4
FC19D29C : eT á : E1A05465 : MOV R5,R5,ROR #8
FC19D2A0 : . Öä : E4D62001 : LDRB R2,[R6],#1
FC19D2A4 : %.2á : E1320C25 : TEQ R2,R5,LSR #24
FC19D2A8 : òÿÿ. : 1AFFFFF2 : BNE &FC19D278
FC19D2AC : ..6á : E136000B : TEQ R6,R11
FC19D2B0 : …. : 0A000014 : BEQ &FC19D308
FC19D2B4 : eT á : E1A05465 : MOV R5,R5,ROR #8
FC19D2B8 : . Öä : E4D62001 : LDRB R2,[R6],#1
FC19D2BC : %.2á : E1320C25 : TEQ R2,R5,LSR #24
FC19D2C0 : ìÿÿ. : 1AFFFFEC : BNE &FC19D278
FC19D2C4 : ..6á : E136000B : TEQ R6,R11
FC19D2C8 : …. : 0A00000D : BEQ &FC19D304
FC19D2CC : eT á : E1A05465 : MOV R5,R5,ROR #8
FC19D2D0 : . Öä : E4D62001 : LDRB R2,[R6],#1
FC19D2D4 : %.2á : E1320C25 : TEQ R2,R5,LSR #24
FC19D2D8 : æÿÿ. : 1AFFFFE6 : BNE &FC19D278
FC19D2DC : .Pä : E4905004 : LDR R5,[R0],#4
FC19D2E0 : ..6á : E136000B : TEQ R6,R11
FC19D2E4 : …. : 0A000009 : BEQ &FC19D310
FC19D2E8 : eT á : E1A05465 : MOV R5,R5,ROR #8
FC19D2EC : . Öä : E4D62001 : LDRB R2,[R6],#1
FC19D2F0 : %.2á : E1320C25 : TEQ R2,R5,LSR #24
FC19D2F4 : ßÿÿ. : 1AFFFFDF : BNE &FC19D278
FC19D2F8 : ..6á : E136000B : TEQ R6,R11
FC19D2FC : æÿÿ. : 1AFFFFE6 : BNE &FC19D29C
*

I have just replied to your duplicate post in csap…

You give no clues as to what version of RISC OS, BASIC or Internet modules are being used, which might help.

Reporter should have shown the BASIC line number of the abort … although no line numbers are given for the code.

I am not sure if the Socket C code is relevant, as the abort seems to be in the BASIC module, just after LOOKU1 label. This is involved in looping round the BASIC variable chains.

r0 & r1 seem to contain “%MI:” which looks wrong, as it is being used as an address that should be the next variable in the chain. It may be followed in storage by r5, which is “SE⁰⁰%” and should be characters 2-5 of the variable name (I think).

My suspicion is that something in Alan’s program has overwritten storage, which has corrupted one of the variable chains.
These can cause some very weird problems. Or I may be barking up the wrong tree totally.

OK. It happens in very specific circumstances. It happens the first time the server is started after a restart, and on ARMX6 running RO5.25 25-Apr-2018, supplied by R-Comp. BASIC is BASIC V 1.75 03 Mar 2018
Internet is 5.63 08 Jan 2018.
It also fails the same way on rpi running RO 5.23 13-Apr-2017, Basic V 1-63 24 Jan 2017, Internet 5.61 17 Jun 2015.
There are 5 databases available. One, which we’ll call TEST is a copy of one I will call LIVE. Selecting LIVE doesn’t cause the crash. Selecting TEST does. Selecting the database does little apart from reading the config file. It also requires that a logging facility built into the software is disabled, otherwise the crash doesn’t happen. The logging code simply writes to a file on the local RAM disc.
I also suspect an overwriting somewhere, but I don’t have enough information to try and work out what and where.
Reporter did issue a line number after the abort, which was followed by the abort again, and the same line number again. The line number was at the start of the error handler.
I have made a small improvement. The error handler did start
*report wimperror running
ON ERROR OFF
As a result the error repeated endlessly.
Changing this to
ON ERROR OFF
*report wimperror running
produced a clean exit.
This says two things: *report was itself producing the error, and adding ON ERROR OFF before it not only stopped the error looping, but stopped *report from producing the error again.
Last time I saw something like this, it was caused by corruption of a variable chain, but I can’t now remember what was corrupting it, or how I stopped it from happening.
r0,r1 and r5 are interesting, as they appear at first to contain part of a variable name. Most of my variables are integers, i.e. ending %, but all are either entirely lowercase, or in a few cases, mixed case. MISE doesn’t appear anywhere as a variable. Nor does it appear anywhere in the database that gets accessed by the time of the abort. The only place MI appears is as MID$(.

I could fiddle around with memory allocation, changing END= etc, but I don’t want to make it go away without knowing why, otherwise Murphy’s law says it will return, just as we go live at the start of a major event.

Not sure if it’ll help much, but %MI: and SE look suspiciously like they’re part of a time format string:

https://www.riscosopen.org/wiki/documentation/show/Date%20Format%20String%20Tokens

Perhaps a symptom of reporter going wrong, since it includes timestamps in its log output.

Thank you – the function at the top of the sequence produces a formatted time and sends it. It’s the sending code that triggers the crash.

*report wimperror running

That (obviously) should not produce an error … but it seems it is :-((
That command has to check if “wimperror” or “running” are variables, so if some variable chains have been corrupted, then I can see it could cause problems.
If you used *report "wimperror running" it should not cause an error, even if the variable chains have been corrupted.

If the ON ERROR is first in the error proc, is the error line still the first line of the error proc?

Incidentally, the report command which includes ~!(readmask%4) ~!(writemask%4) does not look right at all!

The original calling code was:

DEF PROCtimerequest_exec(client%)
LOCAL A$, J%, K%
J%=FNscanchar(client%*2,"#")
K%=datastart%(client%*2)
A$=FNreadbuf(client%*2,"~","#",K%)
datastart%(client%*2)=K
?env%=3
SYS "OS_Word",14,env%
$format%="%W3, %DY-%M3-%CE%YR.%24:%MI:%SE"+CHR$(0)
SYS "Territory_ConvertDateAndTime",-1,env%,names%,256,format%
A$=FNreadstr(names%,0)
A$ = "timeis~time=" + A$ + "#"
IF DEBUG%AND1 THEN *report \R SVR: timerequest_exec: A$
PROCsendmessage(A$,client%)
ENDPROC

It uses several general-purpose blocks that are reused elsewhere.
env% is a 256 byte block, names% is a 4096 byte buffer, and format% is a 256 byte buffer.
names% is used earlier to build a menu, and it is a selection from that menu that calls this routine.

The calling code is now:

DEF PROCtimerequest_exec(client%)

LOCAL A$, J%, K%

J%=FNscanchar(client%2,“#”)

K%=datastart%(client%2)

A$=FNreadbuf(client%2,“~”,“#”,K%)

datastart%(client%2)=K%

?timeblock5%=3

SYS “OS_Word”,14,timeblock5%

$timeformat%=“%W3, %DY-%M3-%CE%YR.%24:%MI:%SE”+CHR$(0)

SYS “Territory_ConvertDateAndTime”,-1,timeblock5%,timebuffer%,256,timeformat%

A$=FNreadstr(timebuffer%,0)

A$ = “timeis~time=” + A$ + “#”

IF DEBUG%AND1 THEN *report \R SVR: timerequest_exec: A$

PROCsendmessage(A$,client%)

ENDPROC

So I’ve fixed it, but I don’t know why it fixed it. I know menu blocks have to be preserved while the menu is open. I assumed you could change them as soon as a selection is made. I wonder whether there is some clearing up done in the background, and I’m changing the block too soon? Having said that, the buffer containing “%MI:%SE” isn’t the menu buffer. The menu buffer is the one receiving the converted string.

Please don’t post code by simply copying it to the forum. Textile will make a mess of it. Because Textile…

To show code, leave a blank line and then write <pre>, then place your code, register dump, whatever after that. End it with a </pre> and you’re good to go.

You can do this multiple times

…if…

you have a number of things to show.

When you do that, we’ll all get to see more or less what you intended (stupid Textile messes up URLs) rather than the gibberish that it would be without.

(example – look at the code you posted a couple of messages above this one. See all the bits in bold? That’s where Textile saw a ‘*’ pair and decided that you meant bold, and your multiply by two just got eaten…)

If the ON ERROR is first in the error proc, is the error line still the first line of the error proc?

No, it is the *report line which is reported.

From my immediately previous reply, changing the buffer from format% to timeformat% stopped the problem appearing. This suggests the variable chain with the problem included format%. timeformat% is a newly created variable, DIMmed after format% in the program.

To show code, leave a blank line and then write

, then place your code, register dump, whatever after that. End it with a 

and you’re good to go.

Thanks. I thought there was something to do that, but when I opened the textile reference I missed it.

I see it’s done weird things to the quoted sample too.

Incidentally, the report command which includes ~!(readmask%4) ~!(writemask%4) does not look right at all!

In case textile has mssed it up, here is how it should have been:

IF DEBUG%AND2048 THEN *report SCL: caller$: before FD_SETSIZE% ~readmask% ~writemask% ~!readmask% ~!writemask% ~!(readmask%+4) ~!(writemask%+4) broadcast_s% server_s% poll_delay%

If I reinstate using format% instead of timeformat% it crashes. However this isn’t used anywhere else as far as I can tell.

Are you sure it is not used anywhere else? You can use *ReportMon to monitor a variable and report if/when it changes – presumably format% should never ever change value.

Are you sure it is not used anywhere else? You can use *ReportMon to monitor a variable and report if/when it changes – presumably format% should never ever change value.

I added that. The output now contains

15:16:58.00 ** Mon   ** format%=196932
some more output then
Value @ 43 format%=571996

Does this mean it’s changed at line 43 in one of the libraries?

Actually, yes it is, but I don’t know whether that routine is called. It’s declared LOCAL and used within a routine. Defining it as local shouldn’t change the outer value though, should it?

The single value change you see is what I would expect if it was not declared LOCAL.
If it was LOCAL, I would expect it first to have a zero value after the LOCAL line, then another value after each change in the PROC, then back to the original value after the line where the library PROC was called.

For example

   10 xxx% = 123
   20 *ReportMon xxx%
   30 PROCtest
   40 END
   60 DEF PROCtest
   70 LOCAL xxx%
   80   xxx% = 999
   90 ENDPROC

16:43:50.52 ** Mon   ** xxx%=123
Value @ 80 xxx%=0
Value @ 90 xxx%=999
Value @ 40 xxx%=123

I’m a bit puzzled then. I get a single reference to line 43. However there isn’t a mention of format% in line 43 of either the main program of any of the libraries it uses.
It’s also interesting, going back to the necessary conditions, that format% is definitely implicated. As I said, it all works if I enable logging, but fails if logging is disabled. Logging calls FNclocktime, which declares format% as local, points it to part of a buffer and puts a format string into it. It then calls OS_ConvertDataAndTime. If this code has been run, everything works. If it is not run I get the failure.
A run with logging enabled starts with:

11:12:15.41 * Mon   * format%=196932

BASIC Stack

   180 PROCserver_comms_init

    82 PROCloadwindow(“choices”,‹&00087094,&00087294,‹0,0,0) [in “Libraries.Slalom_Comms_Lib”]

Value @ 1304 format%=0

Value @ 1307 format%=516978

Value @ 1270 format%=196932

Value @ 43 format%=571984

 1266DEF PROCcommonwritelog(logname$,message$)
 1267IF NOT(logging%) THEN ENDPROC
 1268LOCAL log$,logsize%,freespace%
 1269IF LEN(message$) < (254-13) THEN message$ = FNclocktime2("%24:%MI:%SE.%CS") + ": " + message$

 1302DEF FNclocktime2(format$)
 1303LOCAL rsize%,localtime%,format%,result%
 1304IF LEN(format$) > 29 THEN format$=LEFT$(format$,29)
 1305localtime%=wlib_block%
 1306format%=wlib_block%+30
 1307result%=wlib_block%+60
 1308rsize%=30
 1309$format%=format$ + CHR$(0)
 1310?localtime%=3
 1311SYS "OS_Word",14,localtime%
 1312SYS "OS_ConvertDateAndTime",localtime%,result%,rsize%,format% TO ,rsize%
 1313?rsize%=13
 1314=$result%
 1315

BTW Textile is still messing this up. It was missing various things in brackets, but after adding this comment, it’s stopped doing that. It is still double-spacing some of it.

and a final thought – I was using format% as a buffer to hold a date/time format string to pass into Territory_ConvertDateAndTime. What I hadn’t realised when I wrote the code, some time ago, is that SYS does that for me. It turns out that passing either a string variable or a string literal in works just as well, so I’ve now cleaned up several similar routines.

It’s a result of reading the PRM where parameters are often referred to as pointers to memory. Unless you read the BASIC manual on SYS quite carefully, it isn’t obvious that SYS does it for you.

The changes to avoid using SYS abilities rather than format% within the time function(s) are a good thing … but I suspect that while it has avoided the immediate, obvious, bug, it it has not removed the bug. Looking at the Reporter output with logging enabled, it clearly shows that format% was changed in value, at a mysterious line 43.

Depending on whether it was changed as a result of an assignment, or a DIM, any uses of format% after that point could (and at some time will) cause problems of some sort.

I suggest that it will save future grief if that mysterious line 43 change is tracked down. Personally I would use one of the following:
- TextSeek on a directory known to contain all the source, looking for “DIM*format%” and “format%*=” both with Case sensitive and Enable wildcards selected.
- StrongEd with all the possible source files loaded, and similar searches done with a search of All Texts.

It may also be interesting to look at the values that format% is set to. If Memory: Prog=14,113 Vars=328,360 Free=124,208 Stack=516 Undefined=0 Slot=460K is still representative, giving LOMEM=&B721, END=&5B9DD and HIMEM=&73000, then the format% values look a little strange:

Initial value 196932 = &30144 fine – in variables
PROC value 516978 = &7E372 should be just below HIMEM on stack
Corrupt value 571984 = &8BA50 where is that?!

[Note that *ReportMon ~format% will give values in hex]

I suppose one question is what exactly does ReportMon do? If it monitors the contents of an address, pointed to by the variable name, then something overwriting that address would show as a change to the variable.

I think I’ve eliminated future problems, because there is now only one use of format%, as a local variable assigned to a space in a large buffer, and only in one function. I might change the name of the variable there too.

However following your suggestion I tried Textseek (which I’d forgotten I had) and found that format% was being DIMmed at line 42 in a library, as well as being DIMmed in the main program. I’ve removed it. Fortunately only one program uses that library, so it won’t affect anything else.

This also I think explains the corruption. The main program DIMmed format% as 1024 bytes. The library then reDIMmed it as 20 bytes. Later it put a 30 byte string into the buffer, thereby overwriting the end. What this overwrote then depended on the memory changes that occurred between these two events, which depended on the data being processed at the time.

The original error sequence I now see is that SYS “XSocket_select” returned an error, not from the SWI but from the BASSIC interpreter preparing to call it. Reporter then not surprisingly produced the abort when it tried to check the variables and found a corrupt chain. Without the ON ERROR OFF, it then looped in the abort.

Thank you for all the help.

ReportMon monitors the value of a variable, whatever that is. It checks at the start of each line if it has changed, and if so reports the new valeu.

I am sure that the extra DIM explains the nasty corruption you found, which affected anything looking for a variable (including Reporter).