 The story so far, I am attempting to port Fuzix to the ESP8266. I have the kernel running, I've got a file system working using the Dara.ftl library. This is on the internal flash. I have binaries loading, in it is running to a certain extent. It's crashing partway through startup and I'm trying to investigate what's going on. So last time I spent some time debugging the startup sequence as it crashes partway through the boot process. This is it dead. So I press the reset button, it reboots, it does some stuff and then it falls over. Now, I said that I was going to do some work trying to figure out what was wrong with the file system, which I've done and it turns out to be pretty simple. I was putting a logical file system that was, I think it was about 1400 bytes. 1400K was it. Here we go. 1450K onto the NAND flash and after Dara's overhead for doing the FDL translation the available space was 1465K. Now this turned out to be a very bad idea. The FDL system needs a certain number of free pages in order to operate and there weren't enough. So we were spending all of its time garbage collecting, trying to free up space in order to copy pages. So what I did was I did a very nasty bodge where after filling the file system we copy this file padding onto it, which is full of queues. It's 10MB. Of course this won't fit, so what will happen is it will write as much as will fit onto the file system filling all available free space with queues and then we delete the file. This removes the directory entry, but of course it leaves all the queues on the file system and any additional files will overwrite them. Then my MOOC FDL program detects whether it's copying an entire 512 bytes sector full of queues. If it is then it knows that this sector is unused, therefore it tells Dara that it is unused. And the end result is we have used 850K of the 1465K on the Dara logical device. So all the remaining sectors are empty, this gives Dara loads of space with which to work and as a result everything runs more quickly. So on boot what is happening is I added a bit more tracing in various places. It starts the init program. Here you can see it loading init. Init is now running, it's doing various file operations. Here it is opening a file which is of course the init tab. We get the banner as in it starts up, it does stuff and then it forks. Now what's actually happening is if I load it up, where's the fork line? This is all user code. We are here. So it does the fork. The parent process gets swapped out which is what these writes are doing. The current process becomes the child, so that becomes this stuff here. It does some stuff and then it tries to execute this program called etcrc. That fails. Etcrc is a shell script. Therefore execv will not touch it because it's not an executable binary. And then it tries to run the shell in order to run the script. This also fails because there is no binsh on the file system. We haven't built that yet. Which means that the child process will print an error which is happening here. It prints args to here as rc. Then there's a colon and then it says unknown error 2. 2 is enoent because there is no binsh. It says unknown error because p error actually gets its errors in a file on disk which you can see it try to open here, which obviously doesn't exist. We just haven't copied that on the file system yet. After printing the message it exits, which you can see here. After which we swap in the old process which is in its parent and fall over. And then we spew errors here. So what we need to do is, firstly, we need to get binsh running. Well, we need to get binsh building and put it on the file system. We need to find out where this file containing all the errors is and put that on the file system because that will make future debugging easier. And we need to find out why the kernel crashes when exit is called. So the easiest bit is to find that file. So I've been getting all my files from here. I put them here as part of the MSP430 work but it's all very bit rotted. Like, you know, I think the last time I touched anything was October 19. I don't know why these are updated. January the 21st. Interesting. That's only a few weeks ago. So let's take a look at the library. So library, lib, p error, stirerror is going to do the work. Error.c stirerror. Trying to open pathliberror. Userlibliberror.txt. Have we created user? We've created user but we haven't created lib. So userlib, chmod, cd userlib. Where is our lib error.txt? LibraryLibs. We'll beget libraryliberror.txt. Okay, so let's try. All right, that seemed to work. I'm not going to write the flash yet because we've got some other stuff to do. Such as building sh. Now that's in applications. There's quite a lot of stuff in here now. There's a lot more than there was when I did the MSP430 stuff. So where is sh? v7 command sh. And here are all the other commands so we need to build them too. So I have seen, sorry, pouring myself more drink. I have seen these sh's before. This is, if I remember correctly, this is the original born shell and it is notoriously difficult to understand. This might be a different shell but I really don't like the look of some of this code. I know it works. Anyway, we need to build it. So let's copy the utl makefile application v7 and this is going to need a fair bit of fiddling. So all the stuff in utl's were each source file turned into one binary. With this, this is all built as a single application. So this actually needs a lot of simplification. NS is not defined. So what happens if you build this? Interesting. So that should be defined in library. There is no utemp. Interesting. Wait a minute. This isn't the physics utemp. This is a different one. Okay. Right. What's happening here is that this is supposed to be configuring the compiler and where all the include paths are. And the built-in, the picolibc which I installed way back when has installed its own headers which we do not want to use because they're being found in preference to the physics ones. So we want to add our headers first. Does that work? No. Okay. I'm looking for a way to change the order. So c has to include file lists. There's system ones and user ones. And minus i by default adds user ones. However, system ones are looked for first under some circumstances. It's all annoyingly complicated. There are sectional preprocessor options. Okay. Really? Minus i should be in here somewhere. So it's not the same as minus include. Minus include adds a file of directory options which does not seem to be documented. Fantastic. Now one thing I could do is just do nodestudink which will turn off all the system. It will remove all paths from the include directories. However, I don't actually want to do that because we do need the stuff supplied by the compiler. I think it's isystem. So let's just try this. Yeah, I put that make file in the wrong place which wasn't helping anybody. This needs to have another one of those. Okay, there is no ac.c. Or cold.c. Wait a minute. Yeah, I got all this hopelessly wrong. Right. Yes, and this also explains the oddities I saw in the makefile I was copying. In fact, let's just copy one of the original makefiles, replace our rules and just leave it like that and see what it does. That is these relative paths. Because I'm invoking this from a different directory, these relative paths are now wrong. Other bits of the build system, they refer to a physics root variable. But this does not. So we're going to have to do this. And then in the makefile, which is this one, we're going to have to do root equals that, I believe. And then this can become do not like make based build systems. Okay, that did build most of the way. What doesn't it like? Lots of warnings due to this being very elderly code. And at the bottom, it's trying to link against ReadLine. Has that worked? Well, it worked. Okay, and we've got our binary, which is 16k. SH is quite big as binaries go. And this is occupying half our code space. However, I will also build the rest of these binaries. Is this one? Occasions, rules.sp8266. I'm going to lose all this and I've linked. We can keep everything else. All right. And that has built all of our user land. Well, some of our user land. Oh, and I need to edit this as well. Util makefile. Cool. So let's commit that. And then we start doing stuff with this. We want to... We want our SH. So that's v7 command SH. So what else is there? All of these applications. That should be that. So it's AC acton at... Hang on. It's in the makefile. Do you not think that did what I thought it did? No, it didn't. It's backslash that. That is better. So we fetch these applications. v7 command. That one's a duplicate. We also want to change the permissions to make them executables. gitchmodo755. All right. So we go into kernel. We update flash. Is it going to fit? Yes. We've used maybe another 200k. But there's still a decent amount of space left. So while that is writing, which will take a while, let's go and have a look at exit and see what is special about it. This. Not a lot. So what does doexit do? Not much. It's not doing what I thought it did. I want to search for doexit. Why is that so slow? All doexit should do is terminate the current process and schedule the next runnable process. The next runnable process will be, in our case, in it. So I do not recall if we saw these messages, but we can certainly turn them on like so. What does it actually do? It says it's exiting. If in it gets killed, panic because in it can never kill. Sync the file system. Discard the slot in the page map. Close all open files. Current working directory and the root of the file system are no longer in use. Something to do with clocks. Something to do with signals. Free the TTY. Mark ourselves as exited in the accounting. Tell the parent it's ready. Switch to the parent process. I don't see anything there that's particularly on toward. My best hypothesis is that it's something wrong with my code here. And that doFork here is saving stuff in a way that when the parent is switched back in, it's corrupting things. So how is this being done? We just create an eight-slot stack frame. Okay, that's finished. Let's just... Why isn't that working? Syscall... Yeah, right. Okay. So the syscall name here is an array. And apparently it is not stored in the kernel anywhere. So it gets inlined into the object file that uses the array. And we're now using it in two places. No, I think that's actually rubbish or args. Interesting. Well, the default kernel tracing is better than ours. So let's turn ours off. I think I need a clean. Didn't help though. Process.o. Right, okay. Yeah, I was including this file which has got all the definitions in it. Therefore it was appearing in two different object files which will never work. Right, let's run that. Okay, run in it. Swap out. Right, loading sh. I don't know what that means. Well, I believe that we now have the file system working. So let's just take out some of the tracing just to make things a bit less spammy. I know freed panic, I know freed, which is happening in file sys.c, which happens. It happens when we dereference an I node that has already been through, which already has a reference count of zero. What this will mean is that we failed to reference a I node somewhere. This is all happening inside xx. So it could be this. Let's just spread some tracing through here. So the thing I'm wondering is, is this happening from user code? Probably not as we would have received a syscore trace message. It could be happening here. The I node is opened here. It's the actual file. It's the xx bin sh is happening there. We know it's reading the binary. So it's getting to here. So it's either in user code or it's in something in the signal handling stuff. I did see a signal handling trace message. Let's see what this does. We've got 186. Right. So it's not entering. Oh wait, hang on. Hang on. There's a call to do exec. Right. This is bouncing through user code. All right. So it must be something to do with the signal handling. I haven't even thought about signal handling. So where is this sig2 message coming from process.c again? ssig. Could it be this? Is platform do exec returning? That should never happen. In fact, it makes sense to have a panic here. Right. It's running sh. Okay. Do exec returned? Well, do exec is in here. And it's the simplest thing ever. The only way this could return is if the entry point function was binary, which is sh, were to return. On entry to this, a0 is the link register. And it's not modified when we call into user code. So if sh's entry point was wrong somehow and it was to return, it would end up returning from do exec. That would be bad. So this suggests that our sh makefile is wrong. Now it's v7 command sh. Okay. Yes. So we start at odia. That's not right. And I know what this is going to be. This will be that I put some debug code into one of the two CRTs and then either failed to rebuild after taking it out or left it in. I left it in. Okay. So this is a long and annoying rebuild process. That's the libraries. So we need to build the utils. Okay. v7 command. We need to build these. As good as we don't have to do clean. We need to do these. And we need to update the flash and write it, which will take forever. This doesn't explain why we get the crash on exit, however. And I also do not like that the only difference between these two files is this single call. We could comment out the code and use the preprocessor to decide whether to call this or not. That would probably be better. And while that's building, let's do that. So we're going to copy this to here. I'm a little unhappy about this being the comment character, but I think it's the capital S, so it's been run through the preprocessor. I think the preprocessor is smart enough to know the difference. So this then becomes CRT0 template ESP8266. Let's make that a def, actually. So what's it actually done? There does appear to be nothing there. All right, so even though it's a capital S, it hasn't run it through the preprocessor. Yes, that's because it's actually invoking the assembler directly, where what we actually want to do is we want to build these with the, here we go, with the C compiler, and that should do the right thing. So let's try that. It's trying to link it into an actual, okay, here we go. I'm a little surprised as to why that... Oh, huh. Well, I'm going to have to reflash again, which is annoying. Yeah, and again, the build system's not smart enough to know that they are to know about the dependency. So I'm going to have to put that in myself. So CRT0 depends on template platform.def. Yep, that file is wrong. Library.libs.template. Interesting, it's not honoring the mode line. Possibly it doesn't understand that comment character, but... Oh, come on, why isn't this building? I did tell it about the dependency. Does this need to be the... oh, I didn't think it did. Apparently it does, oh well. But it's still only building one of them. I also know that putting multiple files on the left-hand side of a pattern in make doesn't do what you think it does. So let's just do that.o. It's only built one of them. It is continuing to only build one of them. Okay, so it does know about both files, which both exist. So this is the version for nos.io, so we just want to include the template with nothing in there. Ah, ah. I put these dependency rules here, which meant that without a... That turned out to be the first rule in the file, and that when you invoke the make file without any arguments, it finds the first one, which is not the one you want, so... Do not like make. Do not like make at all. Right, and that's built both. Okay. And once more. Applications, util, make.esb866. Applications, v7command, capital V, v7commandsh, hflash, and write. And while that's going, I'll take the opportunity to go and make some tea. Okay, tea has been acquired. So let's burn this again and see what happens. See whether it actually starts up sh. Well, this won't actually give us an interactive shell. This is going to run the startup script, if it works. Okay, running sh. Oh, it's doing stuff. It's doing lots of stuff. It's stopped doing stuff. Okay, let's have a look and see what happened. So exec init, exec, trying to run RC. Here it's running sh, sh is now running. It's doing the things. Right, sh has been swapped out in favor of another process. I, so here it's forking. Here it's doing the low-level fork. Shouldn't we be seeing an exec somewhere? No, we won't be seeing an exec until it actually, until the child process actually tries to call exec, which is happening here. So here it's trying to run RC. That should fail. Yeah, you see it returns minus one with this error code. It's, yeah, this is the file name. So now it's opening the file name. Now it's running the script. So we fork, we run fusuk, which in turn runs fusuk fusiks, which I believe does not exist. Yeah, exec here returned error code to two. So that's actually going to print a message. It doesn't actually appear to have. So fusuk should be returning. It's swapping in process two, which is sh. It's then forking again, presumably for the next command. And then it stalls. So this could be the same bug, the exit one. I'm just trying to think. This is actually not the most convenient for testing with, as it ends up running lots of complicated stuff. Is there something I can run instead of init that will start up a shell, start up a process, and immediately terminates. I can run fusuk. Because fusuk will immediately try, it will fork and immediately try to run a fusuk fusiks, which doesn't exist. So let's take a look at kernel start.c. Where would I be if I were an init string? I would be here. So let's change this to bin fusuk. Build that and see what happens. Right, running fusuk. That did everything right. So it executed fusuk. Fusuk then printed an empty message and exited. Excuse me. Which is not really what I was expecting. Do I need argument? Let's just do what the RC script was doing. Which is fusuk minus a slash. Okay. Yeah, again, that did everything right. It exited. The parent exited. Oh, wait a minute. This isn't forking. It's not starting fusuk fusiks as a child process. It's just calling exec to replace itself with it. Otherwise it would be swapping itself out. Blast. How about sh? We can do that. That will start a sub shell. And while sh is quite big, true is quite small. So sh is loading. Swap out. Swap in. And it stalls. Well, it hasn't crashed, which is a bit of a shame. What it's doing here is it's dumped the process table. So each of these represents one runnable process. And we have two. We've got this one, PID 1. And we've got this one, PID 2. PID 1 is in it. PID 2 is a status 7, which is zombie. That process has exited and is waiting for in it to repit. That is to read the return status and free up the process slot. So here, I can see that it's swapping in sh. You can see there's quite a lot of it. 16k of code. It's a very exact 16k of code. And then we immediately go to do fork. No, no we don't. That is not where we should be going. Ah, no, no, that is right. It's swapped in the process, resumed it. But of course the last thing that the parent did was called fork. The tracing we get out immediately after the kernel syscall proc. So this is the tracing we get here after do fork returns. So that we can see that do fork. This is this process. Also known as, this is the new process it created, which is of course PID 2. Returns, this is the return code. That's not right. Okay, this gives me a suggestion as to what's wrong. Now remember that the parent returns the PID of the child. So our do fork, which lives in here, we should have saved the PID into slot 5 of the stack frame, which will then cause, it will then cause a switch in to read that value out of the stack frame to return of the tasers code. And if I do 7, 6, 2, 9, 0, that's this value here. The garbage has been returned. And I, that's not right either. Okay, I thought that was going to be a 2, but it's not. A2 is the PTAB pointer. So we save onto slot 5. Slot 5 is not being touched anywhere else. So we read slot 5. IU, because you want to 0 extend it. Really. UI? UI. Okay, what's this doing? Here we go. Do fork returns 2, which is the correct PID. And then it returns 2 in it. But we still get no more tracing. What should be happening here is that SH is continuing to run and then will terminate. So we should see some more system calls and then a panic. So the fact that that is still crashing is annoying. This is where a debugger would be really useful. And in fact, I do have a shiny new JTAG debugger, a clone of an Altera USB blaster. But I tried to build OpenOCD with the ESP8266 stuff in it and it doesn't work. So that will need a bit more research. I am still guessing that what is gone wrong is something to do with this code. Because the only thing that's different here than elsewhere and all this stuff worked is that we are returning to the parent process. Of course, we did see previously that the parent process was working, that returning to the parent was working just fine. Let's stick this tracing back in. Of course, we can't use the system call names. And we also don't want to dereference EF because we were seeing last time it was mangled. Aha! Right, that is more what I was expecting. We see here. Oh, interesting. Disassemble that. And 4021270C. So this is the entire code to printf. It has... A12 is... It's got to be... Wait. So this has got to do with the extensor's kind of odd shifting mechanism which I haven't looked into yet, so let's go and have a look. Set shift amount for little-endian byte shift. This writes a value into sa for a right shift, a multiple of 8. The right shift amount is the two least significant bits of the address register multiplied by 8. SSA atel is the same but for left. So it wants to do a shift of whatever the contents of A14 are multiplied by 8. Now A14 was set here... Ah, right. The reason why this code looks weird is because this has been compiled with the 32-bit access parameter. So that anything that... Any code generated by the C compiler that's not a... That's an 8 or 16-bit value is actually going to be accessed as a 32-bit load or save plus bit shift. So what this is doing, all this stuff, and the reason why it's so complicated, is fetching values and extracting fields. So this instruction, xdui, extracts bits 0 to 8 from A3 into A3. So we shift right by 2. Okay. Shift the contents of the register right inserting zeros at the left by a constant amount. There is no surly for shifts greater than or equal to 16. So that's a simple shift. So what on earth is this doing? Ah, it's setting up a value for this. And sorrel. Shift right logical. Shift by the number of bits in SAR. Okay, 270C which is here. This is rounding A14 right. I know what this is doing. A14 is an address. This is pulling out the bottom two bits of the address and putting it into SAR. That will indicate whether it's a 0, 1, 2 or 3 offset within the word. These two instructions are then truncating the bottom two bits by shifting right by 2 and shifting left by 2. The end result is that bottom two bits become 0. Then we dereference the pointer to read the 32 bit value. Then we shift it right by the number of bits to be pulled off the bottom of A14. And then we extract the bottom eight bits of it. So this is doing an eighth bit access of whatever is in R14 which in this case is going to be Udata. So Udata should be in L32R somewhere which will load the value of Udata because Udata is a constant. I don't see one. This is the only reference I can see to A14. Oh, here's one. So here is another reference to a Udata which is in A13 which is A12 plus 8. This is doing lots of references to... Okay, here it's loading Udata into A12. Right. It's computed Udata plus 9 here and put it into A14. So... What's happening is that GCC has been clever about its various offsets. This is very, very much sounding like that A14 has been corrupted. So let's do a bit more verification. I don't know whether this will work. It may just stir the code enough. Of course, Udata is on the user stack. Udata is zero. No, sorry. Udata is not on the user stack. At this point we're on the kernel stack. Udata is a constant address anyway. It's in memory. So yeah, I think that we are corrupting registers. So here is where we're saving the registers onto the stack frame. And here is where we're loading them. The old stack pointer is stored at this address on the Udata. We load it here. We then load A12 from slot 0, A13 from slot 1, A14 from slot 3, A14 from slot 2, A15 from slot 3, A3 which becomes Sa is from slot 4, A2 is from slot 5, A0 came from slot 7, and then we retract over the old stack frame and exit. Now this will exit into the do fork routine, which is here. So it will then go and call lots of stuff and do lots of stuff as it exits from the routine. Actually this code won't be executed, but it is going to be doing this bit. Fork then will return to Unix syscall, which is in process.c. It's in kernel process.c. We then print our return value and then we do lots more stuff, such as checking for signal dispatch. Then we return to here, at which point we discover that the contents of our registers have been corrupted. Our old Udata was in A14. So if our registers were being corrupted by the switch-in-switch-out process, I would not expect any of the rest of the syscall code to work. So why is it suddenly failing here? It sounds like Unix syscall is not saving A14. Here is Unix syscall. It's saving A14. It's using A14. Things I may have forgotten... Do exec is calling isync before returning, because we've just written to the instruction memory. On swap-in, that also happens. Possibly I have forgotten to do that. So let's just make sure that we do do an isync. But I don't think that's it, because this looks like a data error rather than the code error. We should also actually... Is there a rsync? There is an rsync. No, that does... for isync. So we don't have to worry about... We don't have to worry about synchronizing the data cache when we are reading back values from data. I mean, if that doesn't work, then the cache doesn't work. Memory weight. Make sure that all previous memory operations complete. That's cool. There's a min instruction. I actually rather like this instruction set. It's nice and dense, and looks like it's got lots of features. It's possible that... No, I was thinking that maybe there was a caching issue that meant that after we loaded the new process, when we were loading back the registers, we would get stale values. But again, this is all going through the data cache, therefore it must be correct. The only times this could not be correct is when we actually return to the process and we start executing code from the previous process that hadn't been flushed from the cache. I don't think we're getting that far, but let's just try that anyway with that isync in place and see what happens. SH, swap out, swap in, and it falls over. We needed this anyway. So at this point, we are on the right stack. Okay, so maybe the stack's corrupted. Let's actually... I should have some tracing here that tells us... No, I got rid of it. Let's just find out where the stack pointer is approximately. It's... Let's do this. So this will calculate how close the stack pointer is to the uData block that causes above uData. I don't think we've run out of stack again, but again, if the stack had been corrupted, how are we even getting this far? Interesting. uData should be below the stack pointer, but we would only be getting that if it was above it. Are we on the wrong stack? Oh, and I also want to find the previous syscall. Here we go. 1472, that's the number I was expecting. That's not the number I was expecting. Okay, swap out. Swap in, swap out. So 3FFB4D0 is... It is the user stack. Let's look at previous system call. Oh, it's always that, but we put in code to switch stacks. We're crashing here now. Okay, we're looking for syscall handler. If this is doing what I think it is. Okay, so here's how we do the printf. a3 becomes ea1. That should be cause. That's the stack. Yeah, that's correct. Cause is apparently the first value... No, wait, this is saving a3 on the stack. So a3 is the value of cause. We've saved a3 on the stack. Right, and now the stack pointer has been set to a3 before the call to kprintf, which means that the first parameter, this one, is the actual stack pointer. So let's take a look at our syscall stub. We save the user stack. We switch to the kernel stack. 3FFB4D0. We take a look at those addresses again. I do keep re-misreading 3FFB. It is... Right, that is the kernel stack. I'm an idiot. I was getting this block mixed up with this block. Yeah. Okay, that is therefore the right value. I notice there's always the same stack pointer for every syscall, which is exactly what I would expect because it's doing the same piece of code. So it's actually going to be the values on the stack which are important. Udata here is af19. It's always af19. It looks like this has died on exit. Let's do a little... So let's dump the stack and see what there is to see. This is coming perilously close to changing the code enough that whatever is going on might not manifest. That's it doing all the system calls. So we see our own local stack frame, which is probably the zeros, because everything happens in 16s in this architecture. And then... Oh, 48 bytes. So that's 16... Yeah, that's only 32 bytes. But let's take a record of this and then scroll up. So this is the shell calling in it. Now the shell trying to execute true. Somewhere in here should be our fork. Our fork should be syscall32. So 35, syscall1832. Here is the fork returning in the child. And we see garbage. Here is fork being entered. So that this is the stack that we should be seeing here. I think that's just all wrong, actually. So here it's writing a3 onto the stack. Here it's calling printf. That's a2, a3, a4. We're interested in the computation of a4. So loading via a2. a2 is the sum of the stack pointer. That's ampersand cores. And a2. And a2 is a5 shifted left by 2. a5 is our loop counter. This is multiplying it by 4. This is looking dead suspicious, actually. So what are we actually storing? The address of well a3, which is the cores, is being written to 0.0. That should be showing up there. That's that one we're seeing here. But when this returns there's nothing of the kind. This is what we like to call in the trade completely buggered. So why is that wrong? Signs do point to something around our fork and return routines. I am going to change this to 16. That will just dump 64 bytes. So that will show us the 48 bytes of the mains of Cisco Handlers stack frame plus 16 bytes of Unix Cisco stack frame. No, sorry, it doesn't work that way around. 16 bytes of the parent callers stack frame. And it dies. So what we see is this on entry. Where's that fork? 35, 35, 18, 32. This is fork returning in the child. This is fork being entered. 64k of code plus 31.5k of 64k of data plus 31.5k of code plus 1.5k of Udata is 97. 1.5 plus 1.5 is 33. Swap size looks like the right number. We could be overwriting the Udata block shows up first in the swap. We could be overwriting the Udata of one process by another. That means the order in which we write them will very much affect the behavior of whether it breaks or not. In fact, we can see all these numbers here. So this is Udata writing 1536 bytes at block 291, which is three blocks long. And in fact as each swap each swap slot is 97k which is 194 blocks. That seems like a wrong number. Map time swap size, that looks right. How can we get to 291 from an integer? So, where's our fork? Right, we are writing to by swap size. I've got my parentheses around swap size. This isn't kilobytes, it's blocks. Oh, it's all my swap slots overlap each other. Okay, let's try this. Okay, running SH swapping out, running true, swapping in and it falls over again. Exactly the same behavior. It's now writing 582 which is slot 3. That's interesting, why is it swapping to slot 3? So what is wrong now? Let's take a look at the file system image. File system image is 777 sectors which is well it's starts at 1 and ends at 7 which is slightly more than 4 stack slots. Swap slots. I believe we do have enough space in the swap partition for all of our swap slots. Therefore we can't be overwriting the end of the swap partition. Now let's just take a look at the swap tracing. So we start at 582 which is slot 3. 585 is where the code starts. So we should be writing 3 blocks. Well we can tell how many it is which is 3 blocks at this address and we are writing from Udata. That's correct. When we swap in we're writing to Udata. So we're writing 16k from 713 onwards which is 32 pages. So that's 745 which is not using up all of our stack slots. But this is still garbage. See this looks right. So this is a valid stack frame which we can tell because it's got 1 as the cause. This is not a valid stack frame because we can tell because it's completely different. But how does it get here? It shouldn't be able to return as far as .c with the stack frame garbled like that. Unix syscall will actually appear above the stack frame we're seeing. And Unix syscall will do stuff like save a0 onto the stack. If the stack has been corrupted then it will load back the wrong a0 and fail to return properly. The only possible explanation is that it's only this bit of the stack that's being corrupted. Is USP being touched anywhere? Only in our code. What's this doing? That's debug code. We are storing the stack pointer in the right place which is A3 is Udata. This is us storing it. This is us loading it. Swapper should have done the work of copying the new stack frame. Here we're loading a0, the link pointer, out of the stack frame that we just restored. It must be at least slightly correct. Let's try this. Let's comment these out. On Entry to Unix this call let's dump the stack frame and on Exit let's dump the stack frame. Let's also put that in. What's this going to do? Apart from reducing lots of tracing. This looks like it's finally doing a garbage collection. It hasn't crashed but it's hung. This is what we got. This is a normal looking stack frame and yes, it looks like a perfectly normal looking stack frame. That's different. Let's go find the other side of that fork. This is the child returning. This is the parent. This is the parent's entry and this is the parent's exit. This code, this disassembly is stale but it looks like assuming that it hasn't moved the link pointer is at 28 which is 7. I'm trying to remember my 4 times table. 7. 7. No, that's not right. So where does it put it in the new code? 76, really. Yeah, that's not appearing on this. Yeah, this hasn't actually told us much because the stack frames on entry and exit are actually different. We could move this code to either side of the dispatch. Would that tell us anything? We would expect the stack frames to be the same. So let's see if they are. We can get rid of this. I am wondering if there is actually corruption happening to fix location in the Udata block and as I'm changing the code because the stack usage is changing it's the behavior is slightly changing. Okay, so that's exit swapswap entry. These values are different. See, that's a ROM address. This is a data address that's actually Yeah, this is ROM code. This is ROM data. This is quite different. That's an integer and this is a address. Yes. And if I look at the other routines. So here is syscall 31 sbrook. This is entry. This is exit. And they are the same exactly. All right. Let's take this tracing out and we know that this has called this piece of code and dofork here is doing the bulk of the work. So let's put this in. Now we can use and I'll just add the variable. We also need to change sys.c and get rid of that. Okay, what's this doing? And we die. So an exit. It's now there easy to find. This is the child returning. This is the parent entering. This is a different value. Intriguing. That 5 being different is actually rather reminiscent of this. Because we're actually using slot 5 for the the PID. And that's a perfectly normal looking PID. I was actually expecting 2 in this case. But this is entry and this is exit. So it dumps the stack and then it calls dofork and it allocates an 8 byte stack frame. It loads stuff on the stack frame and it saves the stack pointer here. And here it loads it back again and then here it loads stuff off the stack frame and here it restores the stack frame. So this stack frame actually appears above this one in memory. So as far as this code is concerned, it stack pointers about here and this is sp plus 8 slots. Now we're calling swap out while running off the current kernel stack. We're writing the whole udata block off including the stack we're currently running. But that's okay because we're going to ignore that on load. That goes here. This is all allocating more stacks. It calls here to swap in out. And this is where the udata block gets written and read back again using the same piece of code. I don't think this address needs to be aligned. I mean it can't be aligned because we've been successfully swapping stuff in and out. So buff here is the pointer What's this doing? Okay. This goes from a pointer into user memory to the pointer where that bit of user memory currently is. Because again this is intended for a memory management system so you can swap blocks in and out all over the place. But that's a no ops, that's fine. This doesn't need to be aligned beyond the usual 32 bit alignment. So that's a little bit different but not much. Alright then, well let's try this. So now we switch off the kernel stack calling swap out and doing all the rest of the stuff. No we can't do that because we need to stay on the stack for restoring stuff. We could swap out while doing this. Honestly I don't think it matters. And let me think Where is the kernel stack set up? It happens in When do we switch to the kernel stack? It only happens in do fork not do fork system call handler trampoline this U block size What is U block size again? U block is in kernel LX106 512 by 3 which as I verify several times before is 1536 bytes. Save the stack pointer switch to the kernel stack allocate a minimum block off the kernel stack call the system call handler load back our saved registers which includes and is limited to a0 the link register which is in slot 1 and a2 the exception frame which is in slot 0 retracts back over our stack frame which is in fact no longer needed and switch back to the user stack then return now given that this is the very top of the stack then our code that dumps the stack which I put in process.c here no I didn't I put it in this is called proc here is actually happening here so I think we will actually be seeing over the top of the stack block we are right at the very end of the U data block here and the reason why I printed the address is so that I can see where this is actually where each slot is ok swap in crash ok so here is here is our exit stack frame keep going up until we find fork child 572 36 and 31 18 18 and 17 36 2 47 20 29 38 31 31 32 right this is entry so here is our stack frame before calling the system call and here it is after we are no longer seeing that one because we are not forcing cores to be written to the stack so this is slot 5 which is a very different kind of pointer let's take a look at image.dis syscall trampoline syscall handle trampoline this is where we are loading the kernel stack I was hoping to see the address here but it's not ok so the udata block is at af10 and the swap stack starts at bf10 so we haven't actually dumped enough to show the location to show the start of the swap stack so we haven't reached the end of the udata block could the swap stack be overflowing in certain circumstances that is very likely and it's easily it's easily tested ok that's the only code change we've made so because if we overflow the swap stack while swapping the process out we'll corrupt the top of the udata block where the kernel stack lives so that on entry ok well that hasn't done what I thought it was going to yeah if the swap stack overflows then it could corrupt the top of the kernel stack so that when we reload that process some of it will be garbage again this doesn't explain why we can successfully return so much ok let's find that fork here we go entry put entry up there for a change exit this looks right everything here is as it is here apart from this value and this is a little bit different but it doesn't look anything near as corrupt as it did previously and this is exit and in fact this is all looking very much like the other entry and exit stacks so I think the swap stack was overflowing so great yet another 512k buffer now with 1k buffer alright let's chop out a lot of this put in it back and see what happens ok running in it doing things many things when reading when swapping something in we're never going to touch the data in that swap slot again so I'm wondering whether it's worth trimming those blocks just to make life a little bit easier for the tl the other thing we'll need to do is to add trim support to the fusics file system otherwise the logical file system will gradually fill up with blocks and number of free blocks will just constantly go down until the system is garbage collecting constantly yeah that's probably a good idea I'll need to add some I'll need to add a way to tell the kernel to trim a block for that but that can wait until after we've sorted out what's going on with the application with whatever this thing that is going on is so much garbage collection ok it's doing something now so much garbage collection ok sh is loading here's for suc, here's for suc fusics swap something in and it falls over 4010 01FC ooh that's code that's user code exception 0 is a undefined instruction illegal instruction that's not a hyperlink illegal instruction called 0 at well at here what process is this I think it's sh well it swapped in process 2 the last thing it did the last thing the child did was try to call fusic fusics which isn't there and then it exited so it should be the shell why is it swapping out 3 here right the shell is process 3 so fusic is process 4 for exit we wake up something this is init returning so 01FC is not code well actually that's perfectly valid instruction is just not the right one so at the beginning of the code we jump to entry therefore this is in fact a constant table quite a big one which goes down to here here is entry so there should be no reason for it to jump to this address this does again suggest that something has gone wrong on returning from the system call well let's do this and try that again ok we run in it you can see here on the left all the addresses it's returning to ok fusic fusic fusics back to init and it dies and it is trying to return to 01001FC which is wrong so I don't think that we've managed to fix our corruption at all by changing that is what the stack size however this is driving me completely insane so I am actually going to take some time out and do that trim thing because it's going to make iterating so much easier yeah no garbage collections now thankfully you can see the reps and ints or rather the ints and rets ef will move depending on the user stack fusic fusics swap init back in and die so it does think that we're returning to 01001F9 and that ef is at this address so let's find the corresponding fork which will be way up here this is PID 2 forking is it this I think it's this ef matches epc doesn't this looks like it's loaded in the wrong udata block which would explain a lot of things I mean it looks like it is a udata block so okay so who forked with a program counter of 01F9 I don't see any yet and this is this is init doing stuff so here's it trying to run rc so there will be okay this is the PID 2 is the shell that is running sh I disassembled init didn't I so into sh.dis dis dis kernel sh.dis 01F9 is still garbage I see no references to 01F9 that suggests that the udata block is not someone else's it's just wrong and it's happened to not be crashing because it's picking up a random pointer from elsewhere here's a 0182 this is PID 4 so yeah this is the fustuk program which is quite small maddening all right we want a trim eye octal by which we can tell a block device to trim so this is a this is the list of eye octals this is how you do things that don't correspond to the normal read write open close paradigm each eye octal and physics is a 16 bit number the top contains various flags saying what they do you know if this flag is set then this can only be used by root this one only be used by the kernel etc so we're going to do hjo trim it's a normal eye octal anyone who can access the block device can write to it therefore therefore allowing them to trim actually makes no real difference is that all we need I think that's all we need we want to in here there is a free block routine here we go which marks a block as freed in the file system I believe this is the block number being freed so here we want to do we want to call an eye octal device normally you need a file descriptor for this but here we go de eye octal so this is just going to be void we don't care about the return code device is dev hjo trim and the payload is a pointer to a block number ok then in our dev flash we need to implement a eye octal call back which need to find someone who's actually done this and copy their code dev HD no do not do we need to add this to yeah ok block dev eye octal is doing the work so let's see if I can find this block dev eye octal is interesting this appears to only support block flush buff eye octals right it looks like there is no plumbing to allow a an eye octal to be plumbed through the block device layer which is annoying so we could implement our own eye octal handler there's a flush operand it's a block device yeah there's a transfer function and a flush function but there is nothing to do eye octals blast I thought this was going to be nice and simple I thought that we could simply yeah yeah we can do this we can do this this needs to be dev flash eye octal we need to do what does an eye octal function look like one of these this can go in here octal fast 8t minor urt request char star data ok and in dev flash we need to implement this function and what it's going to do is to call block dev eye octal ok so we will get this before the block device layer does so that we can test for our particular eye octal and yeah that looks like it's working and if it's not the one we want then we just call block dev eye octal so this is going to be case hgo trim default let's just do that failed exactly as we were expecting block no t block no pointer equals block no t say certain trim this block and let's see what this does I saw warnings t9 oh yeah ok now we should see trim messages go past this will only happen when files are deleted by the file system layer rather than the swap layer so we actually need to add this to the swap layer which is in here swap read this is while there are still some bytes then after reading in any block from the swap partition we then trim it so this now we should see trim messages go past as things get swapped in so swap out and of course now it does a garbage collection swap out continuing to swap out and there you saw it swap in with some trim messages one for each block and by block here I'm referring to a physics block otherwise known as a sector and we just want to wrap these in configs so that people who don't have file systems that need trimming can don't need the overhead ok so the actual implementation of it we need to get the block number if blocknop is less than land. actually this is going to be log2ppb block t dara block t is the number of arrays blocks so if this is less than num blocks then we want to do dara map trim dara block no error code always returns zero and let's just keep the trace message for now so this will actually start trimming stuff when flash blocks are red so this might actually begin to help a bit although we're doing a lot of swapping out and not very much swapping in so your mileage may vary running sh swapping out sh so much garbage collection fuzik fuziks it's trimmed stuff it's still doing garbage collection but at least it's got a bit of information oh oh oh yikes that's terribly wrong terribly terribly wrong I forgot to take the physical block number it takes a logical sector number so we've just told dara to uh we've just told dara to trim lots of stuff that probably have data in them and heaven knows what that's going to do to the file system it's probably mangled so we know the number we want to get to pages that's log2ppb let's just try it and see what happens but I'm going to have to rewrite the file system apart from anything else rewriting the file system we'll reset the dara's idea of what blocks are in use and things will get a lot faster coltty come on this was going to be so much faster if I could use an sd card the flash is dead slow actually the other thing I should do is to increase the clock speed rather particularly if I can increase the peripheral clock speed then all this flash stuff will be quicker this thing's overclockable up to about 350 megahertz I also think that I'm going to have to increase the swap partition a bit there's only four slots and we're actually running four processors no we're not running three in it, shell and fusuk we're swapping out, okay here's fusuk and we swap stuff in as we read and it falls over so this is physical block this is sector okay I believe that's working so let's just leave it get rid of the trace messages so how to proceed with the actual debugging I don't think that ef is corrupt at this point so here is the exit so if I go look for pid2 pid4 pid3 pid2 here's pid2 calling fork we can see ef is 7dc0 which is correct while epc is 4010452 which is nothing like what we have here I've just had a horrible thought how much stack how much user stack is it using well actually I know how much it is because ef is on the stack so 7dc0 what am I doing is that many bytes okay I was wondering in our swapper we're only actually saving 3k of stack so if the stack overflows that are we doing it right well here's our swapout tracing so we swap out udata af10 we swap out the main process data at 8000 5632 bytes then we swap out the stack at e8c0 e e8 c o o that's that's ridiculously wrong what am I doing so I think that this was never saving the stack at all let's see what happens yeah this code needs cleaning up can be made more understandable this the right address now looks correct for the stack fusuk swapping stuff in hasn't crashed still hasn't crashed but it's calling lots of stuff without crashing have I mentioned it's not crashing I mean it's slow as gin but it is working I haven't spotted any xx recently and then it dies now it's crashed that's got a lot further than it had so what's it done lots of swapping I think I'll get rid of this tracing as it's basically spam at this point this has it's printing lots of error messages that's what it's doing but it's hard to see because of all the debug tracing etc mtab cannot create okay let's get rid of some of this tracing normally I say that it's nice when bugs are caused by me doing something stupid because they're usually pretty easy to fix but in this situation in this particular case they really weren't okay we can probably turn this off all of this off okay this is it trying to call set date and failing set date not found what was it doing when it crashed it was at 4.021bacf really that's not in the kernel code that looks like strings so this has done a hyperspace jump somewhere into the kernel I don't know why or where from okay now is there more tracing I can dispense with get rid of this but I won't delete it we might be able to see a bit more of what's going on of course now we get no tracing as the as garbage collection happens okay so I think there's supposed to be an error message here actually like not found or something I can get rid of these yeah it's definite finger drumming I am going to have to figure out what's going on with the SD card I've asked for assistance not really come up with anything I mean it should have worked I can't see any reason why behaving the way it was on the plus side I do happen to know that those pins that we were using for the SD card are also used by the JTAG stuff and they now have a JTAG adapter so not having a SD card attached to those pins is possibly a good thing but this kind of delays would make the system unusable set date, set date not found that's our first readable message coming from SH it's trying to run a shell script here so remount not found mtab cannot create why can't it create mtab etc exists ah I know why because remount can't be found it hasn't been able to remount the file system therefore it can't write to anything and then it dies so it looks like it's trying to swap in init it's swapped out 3 so we've got init as 1 sh is 2 so this script is terminating so that's happening here it should then be swapping in init itself we get waitpid is done something oh that comes from ah right I thought that was some tracing I'd put into init but apparently I haven't right so here init is waiting for any process and will either return this error to indicate that there is nothing to wait for this error to indicate it was interrupted or the actual process so let's just speed things up a bit and we want syscall proc we want to know where waitpid goes and the easiest way to do that is to turn system call tracing on and I think we also want to turn sleep on so now we can see the system calls go past and their parameters which is nice and well that's booting let me get rid of that tracing so you see here this is init has returned ah init is called waitpid any process um and then the kernel process switches to whatever is running normally that kind of hyperspace jump is usually caused by stack corruption it could be corrupting some kind of jump table in memory I did remember to turn on optimization and building those binaries in the libraries didn't I oh come on incidentally if you've ever used a solid state disk and it's got full and your system suddenly grinds to a halt and you've got no idea why um there's nothing using a lot of cpu it's just slow it could well be because your solid state disk the latency is suddenly shot up because it's spending all of its time garbage collecting trying to open up space and the solution is either to turn trim on to allow the system to free up space to the ssd or to you know delete loss of files right so what has happened we've swapped in the process in slot 194 and given it's quite big a lot of processors that are 16 3 yeah well this one has a different code size I think this is swapping in and out in it a lot and in it's just quite big or possibly the shell whatever it is it's been swapped in it's in it it's called weightpid oh but the shell does that to it's 3 yeah I don't know what it is but I see it exits we send a signal to process2 that is in it being told that the that the process is exiting but we jump off into nowhere before returning from the system call so we get the gets proc returning message which is process.c and then it dies shortly after so it must be returning here oh wait a minute no no no we're in we're here this is for single tasking wait wait we are single tasking why do I have this in the wrong mode I think this is happier so what that option does is it switches the way the scheduler works to a different type of scheduler it always runs the children before parents when a child dies it will only then swap the parent back in means you can't run stuff in the background but in a single tasking system you can't anyway there's some more sophisticated logic to do with pipes and so on but it means that the current process is much more likely to if the current process won't get swapped out unless there's a specific need I think it will work without it because it just changes the scheduler logic but it would involve lots of swaps in and out and basically thrashing for no real benefit hey it printed a banner it printed the welcome to Fusix banner hey and we've got a login prompt wow that worked um okay I'm not entirely sure why that made it work I mean the get proc code here should still work just not very well so the fact that it the fact that it died platform idle have we called platform idle I mean have we implemented platform idle yeah okay I just wondered whether this was jumping into nowhere but no it is actual real code I mean we can't login because uh the tty doesn't know how to read characters yeah what we need to do is I'm not quite sure what we need to do actually normally the tty is interrupt driven and this this routine here this is stolen from the msp430 code this will read the character from the buffer from the uart buffer and this will poke it into the tty buffer and it will also cause the process to wake up to consume that uh byte we may have to actually do a real tty for that okay that's interesting a little bit unnerving I is that the only place it is indeed so it's get proc and it's timer interrupt which we're not calling you don't have a timer yet um where's process.c so what the timer does is it uh it increments the counters that tell each process how long it's been running for it increments the global counter the global timer and if you're not single tasking it uh looks to see if there are any processors that need rescheduling we are single tasking oh that's where that lives okay we are single tasking and therefore we never wake up processors other than the current one unless it's made runnable by some other reason let me just find the when you get to proc logic in single tasking mode uh if we are ready run if we're not running run ah yes we don't run other tasks pipes work when we turn zombie come back to this parent pipes work on the msp430 so did I it's possible this isn't running in single tasking mode the msp430 is not running in single tasking mode so uh that's because it had fast SD card swap which we don't anyway we have a prompt that's nice suppose the next thing to do is to get the tty running which may involve getting an interrupt handler and get the timer running I suppose find more things executables to put in but once the tty is in place we should be able to actually log in which is nice anyway that was a bit of a shambles but we discovered a number of really nasty bugs and fix them so that's progress uh yeah I will actually I think go through and turn off all the tracing and then check it all in but I'll do that offline so done I hope you enjoyed this video please let me know what you think in the comments