Improving errors

Prompted by this thread I thought it would be worthwhile to try and jot down a list of a few potential ways we could improve the way errors are handled by the OS + apps.

• Many error messages need to be made more descriptive by including some context, e.g. “Device not found” → “Device ‘USB5’ not found” (although in this case ‘USB5’ isn’t likely to be very useful to the user – maybe DeviceFS or USBDriver should be capable of remembering the description text for disconnected devices so the error can include a more useful device name as well?)
• A builtin method for recording errors will aid users and developers in reporting and investigating issues. Default behaviour could just be to log to a RAM buffer, but the user could optionally configure it to log to disc, syslog/network, etc.
• For long error messages, a 256 byte error block isn’t enough, so we need some way of increasing that limit without breaking existing software
• An error number + message on its own is rarely useful. Often errors will be generated from within a series of nested SWI calls and then returned to the outer layer. A programmer will often need to be able to see the full call stack, while users will want a higher-level overview (“Device not found” generated by SomeModule called by SomeProgram called from line 15 of SomeObeyFile)

The last two are going to be the tricky ones. We could bodge in some support by changing the way that MessageTrans works (e.g. have MsgTrans_ErrorLookup generate a second, hidden buffer which contains the full-length error message, and then add a new SWI which will allow code which reports the error text to map from the public error pointer to the hidden internal buffer). But for a non-bodge solution we’ll probably need to introduce an entirely new method of managing errors within the OS.

Agreed. Many of the OS error messages were conceived in a time when programs ran one at a time – very single tasking – so it was obvious what program caused the error, and probably which action and object. In the multi-tasking Wimp world this is no longer true at all – particularly with the layered nature of programs. Perhaps any other prime example cases could be logged in this thread?

If the management of errors is affected, maybe it should include non-blocking Wimp error boxes?! [steps back smartly]

A consistent way of logging errors would be of great benefit – how often have we had to try to copy the more relevant parts of a vdu window?

I think an error generated whilst a particular line of an Obey file is being run (at the highest level) should report the file in which the line that caused the rror resides. For example CLib out of date at line xx of file !Boot.somewhere.obeyfile

If the management of errors is affected, maybe it should include non-blocking Wimp error boxes?! [steps back smartly]

Thank you for putting such a comfortable saddle on my hobby horse :)

All, and I mean all system errors should be logged both to a display message (multitasking please) and to a text file on a convenient file system. All application errors should do the same by default, but a setting in the !Run file could be allowed to override this to produce a blocking error if the current system wide settings allow this. I’m working on the basis that once in a blue moon there might be something that needs to stop the machine dead.

I’m thinking based around SysLog but I’m thinking that a newer version out in Linux land might be a better idea as the base than the current v0.20 that we make do with in RO5.x installs.

Oh, and the prime point for starting with decent logging is at the beginning:- how many times have we had conversations on the subject of which particular bit of the boot sequence died, tripped up etc?

New users arrive, get bewildered and leave. Migrating users (upgrades from RO4.02 being commonest) discover nice things like the “missing sprites” – great there’s a missing file, but what exactly complained in that way?
Oh, and that default logging to file bit – how many times do you find yourself with a totally stiffed GUI and no recorded message of what caused it even though you can connect into a share etc from another machine so you know it’s only the GUI that’s got it’s knickers in a twist and not the file system.

I shall release the reins now…

Jeffrey: I think the advanced error handling should be a part of the Debugger module. In that way, it may be possible to use the backtrace code to unwind C programs from the error point…?

maybe it should include non-blocking Wimp error boxes?!

No. That should be a separate API. Think about it – if an application is “blocked” due to an error being shown, what happens if a user closes a window or drags something across an open window? RISC OS is not compositing, it needs application help. It may be possible to have a minimal API registered with the Wimp as a sort of callback (sorry, precludes BASIC) to perform some polling behaviours when an error box is visible, but the only other way to get this to work is to actually write it into the program with a minimalist polling loop around the error window being shown.

Steve – as I run a server, I wrote a small module to automatically deal with error messages. As I was doing it, I added a tweak where it can record the messages to DADebug as well. I’ve found that useful.
https://www.riscosopen.org/forum/forums/11/topics/3917

New users arrive, get bewildered and leave.

Because of could-do-better error messages? Or because our paradigm is vastly different to how other systems behave. Some that I’ve encountered the most:

• Finding applications, namely the weirdness of ! prefixed stuff in the filesystem being an application.
• Running an application does nothing. User won’t notice a little icon pop up on the icon bar if they’re expecting a big window to automatically open.
• Closing Windows doesn’t quit the application (logical extension to the previous).
• Where are the menus? Are there any such things?
• Using the middle button (usually a scroll wheel) comes across as peculiar if you’re only ever used to systems that use the left and the right.
• What’s with the filesystem and all that punctuation?
• So the system seems to know what sort of files things are, but how the hell does it do that (and you supposed to know) when there’s not one single file extension in sight?

It’s easy for us, many of us grew up with RISC OS since the days it before it even had an outline font renderer, or apps in ROM… But for a newbie? :-)

how many times do you find yourself with a totally stiffed GUI and no recorded message

Rarely. The times I manage to stiff the machine it’s usually one of RISC OS’ big weaknesses, a stack imbalance in module code. Mess up the SVC stack, it’s curtains. Modules probably ought to mostly run in SYS mode but that didn’t exist way back when.

ways we could improve the way errors are handled by the OS + apps.

Could someone wiser confirm that most errors can be, and ought to be, handled by an app while multi-tasking. The default of passing an error back to the calling program, the Wimp generally, is what results in a lot of single-tasking error boxes.

Using the Toolbox I like to present non-fatal errors from BASIC in a modified QuitDialogue, giving the user the error message and the option to quit or proceed. Is that sensible?

handled by an app while multi-tasking

Xxxxx Can be, but it can be a lot more work – perhaps involving a complicated set of interlocks to prevent certain actions from occurring while the multitasking error message is displayed.

To be honest, I often cheap out and just toss the error block at Wimp_ReportError…

[edit: added Xs to get around Textile stupidity]

There are frequently references to SysLog … is it about time that it was included somewhere in RO5? I am still using the DoggySoft v0.20 dated 2003, and I have no idea if it is still the best one to use.

There are frequently references to SysLog … is it about time that it was included somewhere in RO5?

Possibly. There are a few aspects of it that I don’t like, but it is useful, and has been around long enough that a few different apps support it as standard. ROL also include a version in their ROMs.

I think the main improvements I’d want to see would be:

• Ability to log to a circular RAM buffer (necessary if we want to catch errors early on in the ROM / boot sequence, and to avoid upsetting people if disc logging were to result in constant disc activity)
• Support for standard syslog network logging (both server & client functionality). However a brief look at RFC5424 reveals that the old UDP protocol has been deprecated, and all new implementations must support TLS – so this may end up being a two-stage task (part 1 basic UDP support, part 2 TLS once the current network bounty is out the way)
• Configure plugin to control behaviour

It may also make sense to add a plug-in API for handling the messages; that way any number of different types of backend could be supported (e.g. the ability to forward to DADebug, or other bespoke debug interfaces).

maybe it should include non-blocking Wimp error boxes

Definitely need non-blocking error dialogues. Those damned things plague my life…having to write down error messages so I can then open a command prompt to examine why something crashed – its infuriating.

No. That should be a separate API. Think about it – if an application is “blocked” due to an error being shown, what happens if a user closes a window or drags something across an open window?

I believe we’re talking about dialogues blocking the whole Wimp, not blocking one app – that app can be terminated if its reported a non recoverable error and does not need it’s windows redrawn.

If an App has reported an error via the normal ErrorBox, shouldn’t the wimp just then exclude that app from its polling loop until the box has been “closed”. It would only have to check key pressed or mouse clicked in the error box

Jeffrey:

There are a few aspects of it that I don’t like, but it is useful, and has been around long enough that a few different apps support it as standard.

Don’t like aspects of SysLog 0.20, don’t like aspects of RO implementations of SysLog, or don’t like SysLog in general?
There’s a few twists in the versions out there.

Martin:

I am still using the DoggySoft v0.20 dated 2003, and I have no idea if it is still the best one to use.

On RO5.x you don’t really have a choice unless you go get some source and port a newer version.

Jeffrey:

There are a few aspects of it that I don’t like, but it is useful, and has been around long enough that a few different apps support it as standard.

Don’t like aspects of SysLog 0.20, don’t like aspects of RO implementations of SysLog, or don’t like SysLog in general?

All of the above.

• SysLog 0.20 – as mentioned, there are a few improvements I’d like to see
• RO SysLog – the SysLog_IRQMode SWI feels like a hack, it would be better if SysLog itself were able to detect the IRQ state
• SysLog in general – after spending a fair amount of time over the past few years wrangling server code, I’ve come to the conclusion that I don’t like logging systems where the largest unit available is a single line. I like systems where I can log things to a temporary buffer, and have my code decide whether that buffer is important or not. If the buffer is important, anything written to that buffer (both the already-buffered content and any future content) get sent to the logger destination. If the buffer is closed without anything flagging it as important, it gets thrown away. And preferably the log destination understands that all the entries in the buffer are related to each other, so that once you’ve found one log entry from that buffer you can easily fetch all of the other entries.

SysLog in general – after spending a fair amount of time over the past few years wrangling server code, I’ve come to the conclusion that I don’t like logging systems where the largest unit available is a single line.

I suppose there’s two aspects:

1. Doing the standard single line of SysLog as a general log is usually OK and of course far better than no record at all.
2. Single line is quicker to implement, although if it happened to be a single line summary with a link to a fuller record, well that’s cookies and doughnuts¹.
3. I was looking for the low effort version, honest²

¹Which reminds me I need to buy stuff on the way in to work tomorrow.
² Nobody expects the third of two :)

Those damned things plague my life…having to write down error messages so I can then open a command prompt to examine why something crashed – its infuriating.

This post of yours reminded me to dust off something I’ve had kicking around and fix it up.

It’s really simple. It will pick up on Service_Error and will log the error message to DADebug (but could be modified to, perhaps, push the message to serial port or whatever).

Caveat: It does NOT trap a lot of Wimp_ReportError messages. It depends on whether it’s because an actual error happened or the program just called Wimp_ReportError with some sort of message.
However: It WILL log the real error message in times where the Wimp replaces it with “Blah has gone wrong” with the “Describe” button to get to the real message.

Example:

Error: "Application is not 32-bit compatible".
Error: "Application is not 32-bit compatible".
Error: "Unknown or missing variable".
Error: "Internal error: abort on data transfer at &FC1D5880".

In the latter case, the on-screen message was “Application may have gone wrong. Click Continue to try to resume or Quit to stop Application.”
Did not record “The data in the RAM filing system will be lost if you close it down. Click OK if you wish to proceed.” because that’s not an actual error.

; ErrorCatch
; ==========
;
; by Rick Murray
;   Version: 0.01
;   Date   : Friday, 12th January 2018
;
; ErrorCatch - to pick up on errors and log them to DADebug.



         GBLS CODENAME
CODENAME SETS "ErrorCatch"                   ; name *NOT* allocated

         GBLS CODEVERS
CODEVERS SETS "0.01"

         GBLS CODEDATE
CODEDATE SETS "12 Jan 2018"                  ; Date format MUST be "DD Mmm CCYY" for RISC OS to recognise it
                                             ; even though there's no API to parse this date format! :-)
         GBLS CODECOPY
CODECOPY SETS "© 2017 Rick Murray"


; Constants
Service_Error    * 6
Service_ModulePostFinal * &DB

XOS_Module       * &2001E


; ===========
; Here we go!
; ===========

        AREA     |ErrorCatch$Code|, CODE, DATA, PIC, A32bit
        ENTRY

entrypoint
        ; Standard RISC OS module header
        DCD      0                           ; no Start code
        DCD      (initialise - entrypoint)   ; Initialise code
        DCD      0                           ; no Finalise code
        DCD      (servicecall - entrypoint)  ; Service call handler
        DCD      (titlestring - entrypoint)  ; Module title string
        DCD      (helpstring - entrypoint)   ; Module help string
        DCD      0                           ; no Help/command table
        DCD      0                           ; no SWI chunk
        DCD      0                           ; no SWI handler code
        DCD      0                           ; no SWI decoding table
        DCD      0                           ; no SWI decoding code
        DCD      0                           ; no Messages file
        DCD      (thirtytwo - entrypoint)    ; 32bit flag word


titlestring
        =        CODENAME, 0
        ALIGN


helpstring
        =        CODENAME, 9, CODEVERS, " (", CODEDATE, ") ", CODECOPY, 0
        ALIGN


thirtytwo
        ; Zeroeth bit doth be set indicateth this be a 32bit-compatibleth module...
        DCD      1


dadebug_writec
        DCD      0                           ; we write to this word (so this isn't ROMable)

dadebug_address
        DCD      0                           ; we write here too

dadebug_title
        =        "DADebug", 0

error_prefix
        =        "Error: ", 34, 0

error_suffix
        =        34, 46, 13, 10, 0           ; quote, period, CR, LF
        ALIGN


initialise
        ; Module initialisation
        STMFD    R13!, {R0-R5, R14}
        ; Read DADebug's WriteC address
        SWI      &731C0                      ; XDADebug_GetWriteCAddress
        MOVVS    R0, #0                      ; no, so set address to be NULL
        ADR      R1, dadebug_writec
        STR      R0, [R1]                    ; remember this address

        ; And try reading its base address
        MOV      R0, #18                     ; Lookup module name
        ADR      R1, dadebug_title
        SWI      XOS_Module
        MOVVS    R3, #0                      ; Set address to NULL if module not present
        ADR      R1, dadebug_address
        STR      R3, [R1]                    ; remember it

        CMP      R3, #0                      ; hacky way to clear V (R1 will be in RMA (< 2GiB))
        LDMFD    R13!, {R0-R5, PC}


fast_table
        DCD      0                           ; Special ServiceCall table
        DCD      (fast_entry - entrypoint)
        DCD      Service_Error               ; They cocked this up badly. It should have been a series of
        DCD      Service_ModulePostFinal     ; "Service Call, address of handler" pairs, and then the
        DCD      0

        DCD      (fast_table - entrypoint)   ; pointer to fast table (just above!)
servicecall
        MOV      R0, R0                      ; flag that there is a fast case table
        TEQ      R1, #Service_Error
        TEQNE    R1, #Service_ModulePostFinal
        MOVNE    PC, R14                     ; if not one we're interested in, drop out


fast_entry
        ; Since the fast table shunts everything here, we have to work out what to do AGAIN in the
        ; slow case (normal ServiceCall handler).

        TEQ      R1, #Service_ModulePostFinal
        BEQ      module_has_died

        ; Fall through to here if it's an error.

        ; Service_Error
        ;   R0 = Pointer to error block
        ;   R1 = &06
        ; Called after error happens but prior to handler being invoked. DO NOT CLAIM!


        STMFD    R13!, {R0-R4, R14}          ; Stack some registers to give us some room to play in

        MOV      R4, R0                      ; Stash error block in R4

        ADR      R0, dadebug_writec
        LDR      R3, [R0]                    ; retrieve DADebug's WriteC address
        CMP      R3, #0                      ; is it zero?
        LDMEQFD  R13!, {R0-R4, PC}           ; if so, bail

        ADR      R0, error_prefix            ; write the prefix string
        BL       debug_write0

        ADD      R0, R4, #4                  ; write the error message (+4 to skip over error number)
        BL       debug_write0

        ADR      R0, error_suffix            ; write the suffix string
        BL       debug_write0

        LDMFD    R13!, {R0-R4, PC}           ; That's all...


debug_write0
        ; Write the string in R0 to DADebug (WriteC address in R3).
        STR      R14, [R13, #-4]!            ; Stack return address
        MOV      R1, R0                      ; Push string pointer to R1, as R0 holds each byte

write0_loop
        LDRB     R0, [R1], #1                ; read byte from string (and increment offset)
        CMP      R0, #1                      ; is it a null?
        MOVCS    R14, PC                     ; if no - set R14 to be return address
        LDRCS    PC, dadebug_writec          ; if no - write the byte
        CMP      R0, #1                      ; (returns here)
        BCS      write0_loop                 ; keep going until we get a null

        LDR      PC, [R13], #4               ; Back to caller


module_has_died
        ; Has DADebug been quit?
        ;
        ; Service_ModulePostFinal [RISC OS 5.00+]
        ;   R0 = Module address
        ;   R1 = &DB
        ;   R2 = Pointer to module title
        ;   R3 = Base/Postfix
        ;   R4 = BCD version
        ; Called after module has been finialised. DO NOT CLAIM.

        STMFD    R13!, {R0-R1, R14}

        ADR      R1, dadebug_address
        LDR      R1, [R1]                    ; load our saved address into R1
        CMP      R0, R1                      ; is it DADebug?
        LDMNEFD  R13!, {R0-R1, PC}           ; no, so drop out

        ; Yes, it's DADebug being quit, so...
        MOV      R0, #0
        ADR      R1, dadebug_writec
        STR      R0, [R1]                    ; NULLify the WriteC address
        ADR      R1, dadebug_address
        STR      R0, [R1]                    ; NULLify the module address

        LDMFD    R13!, {R0-R1, PC}

        ; There's no mechanism for detecting DADebug being loaded. Just re-load this module...
        ; (and RISC OS doesn't have an API for a module to self-terminate)


        END

        LDMNEFD  R13!, {R0-R1, PC}
        ; There's no mechanism for detecting DADebug being loaded. Just re-load this module...
        END

Obvious bug is obvious.

Obvious bug is obvious.

:-)

Perfectly highlighting the danger of using copy-paste instead of actually typing stuff…

[fixed]