Teensyduino File System Integration, including MTP and MSC

Follow on from previous post. I instrumented the usb isr some more and added to turn on the ISR output earlier... So if less than 64k left turn on the debug output...
I also printed out the USB1_USBINTR value, to see if it should be processing the SOF...

Maybe something interesting:
Code:
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081 USBINTR:01000143
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 01000080 USBINTR:01000143
need to switch to alternate clock during reconfigure of ARM PLL
USB PLL is running, so we can use 120 MHz
Freq: 12 MHz * 66 / 4 / 1
ARM PLL=80002064
ARM PLL needs reconfigure
ARM PLL=80002042
New Frequency: ARM=198000000, IPG=99000000
Decreasing voltage to 1150 mV
*status: 01000080 USBINTR:01000143
*status: 00000080 USBINTR:01000143
*status: 00000080 USBINTR:01000143
*status: 00000080 USBINTR:01000143
*status: 00000080 USBINTR:01000143
...
Not sure what the need to switch to alternate ... comes from here?
 
Another update. @mjs513 and myself have been trying to make sense of some of the above...

What we have learned includes: The USB stuff going nuts and the changing of the clock speed all have to do with a fault happened!

And the unused_interrupt_vector was called... I should have realized that but have not been getting CrashReports.


So: I have core/debug turned on to output to Serial4, I have instrumented my bogus FS code to output debug data on some calls to both Serial and to the debug_printf

And now I added some printing to the unused_interrupt_vector:
Code:
	info->crc = crc;
	////////////////////////////////////////////////
	printf("\n >>>>> unused_interrupt_vector <<<<<\n");
    printf("  Code was executing from address 0x%x\n", info->ret);
    printf("  CFSR: %x\n", info->cfsr);
	if (((info->cfsr & (0x80)) >> 7) == 1) printf("\t(MMARVALID) Accessed Address: 0x%x\n", info->mmfar);
    printf("  HFSR: %x\n", info->hfsr);
	////////////////////////////////////////////////
	arm_dcache_flush_delete(info, sizeof(*info));

Stuff between the lines //////////// are added...

Now I am getting the debug output:
Code:
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
*status: 00000081
data
USB1_ENDPTSETUPSTAT=00000000
USB1_ENDPTCOMPLETE=00000008
run_callbacks
 end of list
Bo*status: 01000080
gus::close(/T4LargeIndexedTestfile.txt)
*status: 01000080
Bogus::close(/T4LargeIndexedTestfile.txt)
*status: 01000080
Bogus::close(/T4LargeIndexedTestfile.txt)
*status: 01000080
Bogus::Bogus /T4LargeIndexedTestfile.txt 0
*status: 01000080
Bogus::setModifyTime: /T4LargeIndexedTestfile.txt 11/5/2021 7:20
*status: 01000080
Bogus::setCreateTime: /T4LargeIndexedTestfile.txt 11/12/2021 7:37
B*status: 01000080
ogus::close(/T4LargeIndexedTestfile.txt)
*status: 01000080
Bogus::close(/T4LargeIndexedTestfile.txt)
*status: 01000080
Bogus::close(/T4LargeIndexedTestfile.txt)

 >>>>> unused_interrupt_vector <<<<<
  Code was executing from address 0x0000C5FC
  CFSR: 00000082
	(MMARVALID) Accessed Address: 0x20005300
  HFSR: 00000000
need to switch to alternate clock during reconfigure of ARM PLL
USB PLL is running, so we can use 120 MHz
Freq: 12 MHz * 66 / 4 / 1
ARM PLL=80002064
ARM PLL needs reconfigure
ARM PLL=80002042
New Frequency: ARM=198000000, IPG=99000000
Decreasing voltage to 1150 mV
*status: 01000080
*status: 00000080
*status: 00000080
*status: 00000080
*status: 00000080
*status: 00000080
*status: 00000080
*status: 00000080
*status: 00000080
...
And all of those status ones are where the usb_isr is being called from unused_interrupt_vector...
One curious question in crashreport, wonder why we print out HTSR for HFSR? (Typo?)
Code:
    if (_HFSR > 0) {
      p.print("  HTSR: ");
      p.println(info->hfsr, HEX);

Now to see what these addresses are...

EDIT:
Code:
C:\Users\kurte\AppData\Local\Temp\arduino_build_Bogus_MTP-logger.ino>addr2line -e Bogus_MTP-logger.ino.elf 0x0000C5FC
C:\arduino-1.8.16\hardware\teensy\avr\cores\teensy4/memcpy-armv7m.S:125

EDIT2: and the address: 20005300 g .bss 00000000 _ebss
 
Last edited:
It could be possible that memcpy crashes if it accesses a a) unaligned address where it is not allowed (0x20005300 IS allowed and aligned) - or b) if the MPU is confused. - or c) - well ... have no Idea. Silicon bug?
I'd try to just disable the MPU for this test. And if it's only to rule out the MPU.
 
Thanks @Frank B:

I think it is LittleFS_RAM

I just updated the debug code I added to: unused_interrupt_vector
To try to print some stack...

Code:
	////////////////////////////////////////////////
	printf("\n >>>>> unused_interrupt_vector <<<<<\n");
    printf("  Code was executing from address 0x%x\n", info->ret);
    printf("  CFSR: %x\n", info->cfsr);
	if (((info->cfsr & (0x80)) >> 7) == 1) printf("\t(MMARVALID) Accessed Address: 0x%x\n", info->mmfar);
	printf("  XPSR: %x\n", info->xpsr);
    printf("  HFSR: %x\n", info->hfsr);
    printf("  STACK: %x PSTACK: %x\n", (uint32_t)stack, (uint32_t)pstack);
    for (uint16_t i = 0; i < 32; i+=4) printf("\t %x %x %x %x\n", stack[-i],stack[-i-1], stack[-i-2],stack[-i-3]);
	////////////////////////////////////////////////
Code:
 >>>>> unused_interrupt_vector <<<<<
  Code was executing from address 0x0000C5FC
  CFSR: 00000082
	(MMARVALID) Accessed Address: 0x20005700
  XPSR: 21010000
  HFSR: 00000000
  STACK: 20067EF8 PSTACK: 00000000
	 200054E0 00000000 00000000 20067EF8
	 200024EC 0000D6CB 20067EF8 00000000
	 20067ED8 20067EFC 20004320 20067E52
	 00000010 00000014 00000007 000007E5
	 00000005 0000000B 6184DB30 20001E78
	 00005CE5 20067DC0 000007E5 0000EFA5
	 00000014 20004F74 00000025 00000007
	 014FEFF4 00000001 00000012 20067DFE

I looked at some of these addresses:
Code:
C:\Users\kurte\AppData\Local\Temp\arduino_build_Bogus_MTP-logger.ino>addr2line -e Bogus_MTP-logger.ino.elf 0x0000d6cb
C:\arduino-1.8.16\hardware\teensy\avr\cores\teensy4/startup.c:568 (discriminator 3)

C:\Users\kurte\AppData\Local\Temp\arduino_build_Bogus_MTP-logger.ino>addr2line -e Bogus_MTP-logger.ino.elf 0x00005CE5
C:\Users\kurte\Documents\Arduino\libraries\MTP_Teensy\src/MTP_Teensy.cpp:552

C:\Users\kurte\AppData\Local\Temp\arduino_build_Bogus_MTP-logger.ino>addr2line -e Bogus_MTP-logger.ino.elf 0x00000007E5
C:\Users\kurte\Documents\Arduino\libraries\LittleFS\src/LittleFS.h:428

And if you look at LittleFS.h we see:
Code:
	static int static_prog(const struct lfs_config *c, lfs_block_t block,
	  lfs_off_t offset, const void *buffer, lfs_size_t size) {
		//Serial.printf("    ram wr: block=%d, offset=%d, size=%d\n", block, offset, size);
		uint32_t index = block * c->block_size + offset;
		memcpy((uint8_t *)(c->context) + index, buffer, size);
		return 0;
	}
And line 428 is the memcpy... And this is under LittleFS_Ram... And the MTP code is at about this time trying to write to its storage list with the object information just created...
 
The memcpy is used in a million sketches and "thousand" of times in the core - both T3 and T4. I can't imagine any reason why memcpy should be the problem. It just shows the problem.

Don't work around. It *MUST* work with memcpy. The reason for the crash is something different. A workaround would mean not to fix the problem but the symptom only, and the problem will return later somewhere else...
 
The memcpy is used in a million sketches and "thousand" of times in the core - both T3 and T4. I can't imagine any reason why memcpy should be the problem. It just shows the problem.

Don't work around. It *MUST* work with memcpy. The reason for the crash is something different. A workaround would mean not to fix the problem but the symptom only, and the problem will return later somewhere else...

One step at a time... As I mentioned a couple posts up it faulted in memcpy where it appears like it addressed _ebss...

But as you mentioned there are lots of places that call memcpy... So it is why I extended the debug otuput... And then try walking the stack... Now looking at code:

The mtp test sketch I am looking at puts the list of objects file on the RAM drive which in my case I created as a 4mb FS in PSRAM...

Now trying to see if anything jumps out at me in the LittleFS code...

My guess is it is related to the calls in MTP to update the date/time stamp:
Code:
bool MTPStorage::updateDateTimeStamps(uint32_t handle, uint32_t dtCreated, uint32_t dtModified)
{
	Record r = ReadIndexRecord(handle);
	DateTimeFields dtf;
	if ((dtCreated == 0) && (dtModified == 0)) {
		MTPD::PrintStream()->printf("&&DT (0,0) (%u,%u)\n", r.dtCreate, r.dtModify);
		return true;

	}
	OpenFileByIndex(handle, FILE_READ);
	if (!file_) {
		MTPD::PrintStream()->printf(
			"MTPStorage::updateDateTimeStamps failed to open file\n");
		return false;
	}
	mtp_lock_storage(true);
	r.dtModify = dtModified;
	breakTime(dtModified, dtf);
	file_.setModifyTime(dtf);
	r.dtCreate = dtCreated;
	breakTime(dtCreated, dtf);
	file_.setCreateTime(dtf);
	WriteIndexRecord(handle, r);
//	file_.close();
	mtp_lock_storage(false);
	return true;
}
Probably with the WriteIndexRecord call... But that is only a SWAG
 
The current beta has the date/time stuff. Some of our MTP test sketches have a show directory listing...

Still pulling the last few hairs...

I added some debug output to littleFS:
Code:
	static int static_prog(const struct lfs_config *c, lfs_block_t block,
	  lfs_off_t offset, const void *buffer, lfs_size_t size) {
		uint32_t index = block * c->block_size + offset;
		Serial.printf("    ram wr: block=%d, offset=%d, size=%d context:%x index:%x buffer:%x\n", 
			block, offset, size, c->context, index, (uint32_t)buffer);
		Serial.printf("\t call memcpy(%x, %x, %u)\n", (uint32_t)((uint8_t *)(c->context) + index), (uint32_t)buffer, size);
		Serial.flush();
		memcpy((uint8_t *)(c->context) + index, buffer, size);
		Serial.println("$$"); Serial.flush();
		return 0;
	}
Ran the copy file stuff:
Code:
...21496 RESP:2001(RSP:OK)l: 24 T:9 : 20001 ffffffff 14
21496 CMD: 100d(SEND_OBJECT)l: 12 T:a
MTPD::SendObject: len:22015988
    $$*: 0
    ram wr: block=1674, offset=256, size=256 context:7000000c index:345100 buffer:202019d0
	 call memcpy(7034510c, 202019d0, 256)
$$
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
BogusFS::open(/T4LargeIndexedTestfile.txt, 0)
Bogus::setModifyTime: /T4LargeIndexedTestfile.txt 11/05/2021 07:20
Bogus::setCreateTime: /T4LargeIndexedTestfile.txt 11/12/2021 12:07
    ram wr: block=1675, offset=0, size=256 context:7000000c index:345800 buffer:202019d0
	 call memcpy(7034580c, 202019d0, 256)
$$
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
    ram wr: block=1675, offset=256, size=256 context:7000000c index:345900 buffer:202019d0
	 call memcpy(7034590c, 202019d0, 256)

And the last one did not return...
So thought I would try a quick and dirty sketch:
Code:
void setup() {
  while (!Serial) ;
  Serial.begin(9600);
  Serial.println("START");
  delay(1000);
   call_memcpy(0x7034500c, 0x202019d0, 256);
   call_memcpy(0x7034510c, 0x202019d0, 256);
   call_memcpy(0x7034580c, 0x202019d0, 256);
   call_memcpy(0x7034590c, 0x202019d0, 256);
}

void call_memcpy(void* dest, void* src, uint32_t cnt) {
  Serial.printf("memcpy(%x, %x, %u\n", (uint32_t)dest, (uint32_t)src, cnt);
  Serial.flush();
  memcpy(dest, src, cnt);
  Serial.println("<< Returned"); Serial.flush();
}


void loop() {
}

No faults:
Code:
START
memcpy(7034500c, 202019d0, 256
<< Returned
memcpy(7034510c, 202019d0, 256
<< Returned
memcpy(7034580c, 202019d0, 256
<< Returned
memcpy(7034590c, 202019d0, 256
<< Returned
So something else going on... Like maybe Interrupt during the memcpy? That maybe did not restore all of the registers?
 
What example for PSRAM shows the needed changes to show Time/Date stamp on LFS files?

Found it in \Bogus_MTP-logger.ino, Not seeing any immediate issues where

Running edited function.ino in : LittleFS\examples\Integrity\PSRAM\PSRAM.ino
With edits for more and larger files with prime number of bytes to start and add rather than 512 blocks during create, add, delete cycles:
Code:
 0 dirs with 2 files of Size 53267 Bytes
7_dir                                C: 11/12/2021 13:41 M: 11/12/2021 13:41  /
      P_file.txt                     C: 11/12/2021 13:41 M: 11/12/2021 13:41  28984
      Q_file.txt                     C: 11/12/2021 13:41 M: 11/12/2021 13:41  30551

 0 dirs with 2 files of Size 59535 Bytes
8_dir                                C: 11/12/2021 13:41 M: 11/12/2021 13:41  /
      R_file.txt                     C: 11/12/2021 13:41 M: 11/12/2021 13:41  32118
      S_file.txt                     C: 11/12/2021 13:41 M: 11/12/2021 13:41  33685

 0 dirs with 2 files of Size 65803 Bytes
9_dir                                C: 11/12/2021 13:41 M: 11/12/2021 13:41  /
      T_file.txt                     C: 11/12/2021 13:41 M: 11/12/2021 13:41  35252
      U_file.txt                     C: 11/12/2021 13:41 M: 11/12/2021 13:41  36819

 0 dirs with 2 files of Size 72071 Bytes
B_file.txt                           C: 11/12/2021 13:41 M: 11/12/2021 13:41  7046
C_file.txt                           C: 11/12/2021 13:41 M: 11/12/2021 13:41  8613

 25 dirs with 2 files of Size 15659 Bytes
 Total 50 files of Size 4192368 Bytes
Bytes Used: 4374528, Bytes Total:15728640
 
@Kurt - is Little FS in use the updated version from Mike?
@Mike - not sure if the PR version changed the LIB version number from 1.0.0? What I have from mjs513 github shows 1.0.0

In the file : ...\LittleFS\src\LittleFS.h
There is no reason to flush the cache since the drive is always trashed on restart, the MCU should manage the cache.
> Kurt in that file take out this code - I don't expect it will change anything in the observed error case ... but is wasteful overhead:
Code:
	static int static_sync(const struct lfs_config *c) {
//		if ( c->context >= (void *)0x20200000 ) {
			//Serial.printf("    arm_dcache_flush_delete: ptr=0x%x, size=%d\n", c->context, c->block_count * c->block_size);
//			arm_dcache_flush_delete(c->context, c->block_count * c->block_size );
//		}
		return 0;
	}

Looking for _isr to cause repro with standard LFS PSRAM usage
Further mods to the Integrity/PSRAM with 16MB media on T_4.1_b1.07 : no failures yet have been provoked.

It sends the standard progress DEBUG spew to USB, but with _isr interrupt every 25us it is not showing any problem with LittleFS on PSRAM while using the current Time/Date stamp code.

> Added DirList showing TD stamp before each DELETE pass cycle
> Reduced the rate of Delete pass so files get more adds before delete
> Made the loops cycling over fill the media
> reduced excess # dirs/files so won't over fill
> Brought the IntervalTimer code over from C4CBench : interrupting each 250 us and doing those string compares, and LED toggle to show life.
-- running slower but cycling fine
> Changed that to allow the PROGMEM string to run from DMAMEM - no change with or without arm_dcache_flush_delete in LFS_updated or the _isr code.
>>25us _isr on PROGMEM with arm_dcache_flush_delete() barely moves! Fine without and DMAMEM with or without moves well enough.
 
Kurt - is Little FS in use the updated version from Mike?
@Mike - not sure if the PR version changed the LIB version number from 1.0.0? What I have from mjs513 github shows 1.0.0

Believe Kurt is using the current TD version. I have been using 2.4.1 version to confirm no issues with updating. Right now whatever we see going on in the old version is also seen in the new version

Was doing some testing earlier today with Serial4 turned to capture any issues with unused_interrupt_vector being called with the standard library usuage. And yes I was seeing the same thing as @KurtE posted. In several runs I didn't see it with LFS turned off in the sketch but I can's seem to duplicate that now. Which make me think that the issue is more subtle in MTP - maybe as @KurtE posted in post #481. Going to re-test again now that I have some coffee.
 
Thx Mike. Started with the TD version and then changed to V_2.4.1 and same results - PSRAM working and _isr() not causing grief.

> did a run of 100 loops with _isr spinning on PROGMEM without cache flush at 25 us
> another with DMAMEM with cache flush - had to drop to 250us as the isr was saturating the mcu

> Updated LittleFS working well with PSRAM
> _isr process not affecting the process
 
Did lots of I/O and with _isr running did "B"ig files "BBBb" that filled the disk then deleted the files.
Code:
Bytes Used: 13428736, Bytes Total:15728640

	 Loop Count: 340 (#fileCycle=115112), Bytes read 8,791,363,200, written 1,715,127,608, #Files=274
That is after three sets of 'h'undred loops

That is with just two "BB" big files left and some more loops - also no problem.

When running as configured it is cycling between 6 and 9 MB used as files, delete or grow or create - all with valid TD stamps.

Just edited the _isr to do smaller group byte compares over 4 strings (MAX 19 instead of 104 bytes) so the _isr can run at 100us and still do the arm_dcache_delete() - and added 4 memcpy of the DMAMEM string to the Real RAM string on each of those 10K/sec calls during LFS_PSRAM.

That's what comes to mind for using the Integrity abuse features to emulate 'everything but the USB I/O' that shows the Updated 2.x LittleFS code can run with as noted.

As that is written it occurs since it can run against DMAMEM for the _isr compares and memcpy - it can also run against EXTMEM ...
>> That worked at first - now I've got something having the _isr consume the MCU time ?
--> I need to find and place that other unused_interrupt code just in case ...
 
Why don't you just disable interrupts during the memcpy to see if a ISR is the reason? (for this test only)
If it still crashes it can't be a ISR..
 
Why don't you just disable interrupts during the memcpy to see if a ISR is the reason? (for this test only)
If it still crashes it can't be a ISR..
Thanks Frank,
Like you I don't believe it is memcpy that is the fault... I think it is who is calling memcpy...
And I think I now have a clue...

MTP loop code receives a packet, then when it is done with it, in most cases it copies the message received to the message transmist and changes the operation from CMD to RESP and first parameter is the result code...

Well we received a bogus message:
Code:
LP:CMD: 0000100C l:20
DATA: 0000100C l:194
Bogus::close(/)
Bogus::close(/)
Bogus::close(/)
Bogus::Bogus /T4LargeIndexedTestfile.txt 2
RESP: 00002001 l:24
LP:CMD: 0000100D l:12
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::Bogus /T4LargeIndexedTestfile.txt 0
Bogus::setModifyTime: /T4LargeIndexedTestfile.txt 11/5/2021 7:20
Bogus::setCreateTime: /T4LargeIndexedTestfile.txt 11/13/2021 8:46
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
Bogus::close(/T4LargeIndexedTestfile.txt)
RESP: 00002001 l:12
LP:RESP: 00002005 l:959591472

 >>>>> unused_interrupt_vector <<<<<
  Code was executing from address 0x0000C5BC
  CFSR: 00000082
	(MMARVALID) Accessed Address: 0x20005700
  XPSR: 210F0000
  HFSR: 00000000
  STACK: 20067EF8
	 200054E0 00000000 0000000A 20067EF8
	 20002578 0000D681 20067EF8 2027FF80
	 20067ED8 20067EFC 6000231C 00004EF1
	 20201343 00000000 00000030 00002005
	 00000008 FFFFFFE9 20004340 00002001
	 00002005 41414141 41414141 4018C000
	 2000143C 4018C000 20002194 410F0000
	 6000229A 0000CAE1 20201343 00000000
need to switch to alternate clock during reconfigure of ARM PLL
Which I captured in the using printf_debug()... SO went out to Serial4...
And that last message is totally bogus: LP:RESP: 00002005 l:959591472

And currently the response code did not validate that length field and memcpy with that length... Which is probably not a good thing...
 
Hope you are having luck figuring out why it recorded a 'bogus' packet ... assuming that 'l' is length of a really big number.

Above 'unused_interrupt_vector' edit is where a crash enters - but can't get as far as completing a usable report? So live dumping to Serial4 allows it to be captured?
 
Hope you are having luck figuring out why it recorded a 'bogus' packet ... assuming that 'l' is length of a really big number.

Above 'unused_interrupt_vector' edit is where a crash enters - but can't get as far as completing a usable report? So live dumping to Serial4 allows it to be captured?
Yes the code to output to printf_debug allows us to see the fault data, that I added. It was rare that I would get a valid crash report...

Wonder if I should Pull request those changes in?

Now as for keeping it from crashing... I have pushed up some additional changes, that detects that the message is bogus and does not process it. Also temporarily I have included using my memory hex dump library, and print out the bogus message...
I am still working with my bogus file system as I can muck with it and eliminate other possible things.

My last run showed some interesting data, note right now I have Serial4 stuff turned off.
Code:
LP:28257 CMD: 100d(SEND_OBJECT)l: 12 T:a
MTPD::SendObject: len:22015988
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999
BogusFS::open(/T4LargeIndexedTestfile.txt, 0)
Bogus::setModifyTime: /T4LargeIndexedTestfile.txt 11/05/2021 07:20
Bogus::setCreateTime: /T4LargeIndexedTestfile.txt 11/13/2021 13:19
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:-1
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:-1
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:-1
 # USB Packets: 42999 total: 728 avg ms: 0 max: 1
 # Write: 10750 total:226 avg ms: 0 max: 1
>>>Total Time: 975769
SendObject() returned true
29232 RESP:2001(RSP:OK)l: 12 T:a
LP:29232  UNKWN: 3639
20003D60 - 30 34 32 39 39 36 20 41  41 41 41 41 41 41 41 41  : 042996 A AAAAAAAA
20003D70 - 41 41 41 41 41 41 41 41  41 41 41 41 41 41 41 41  : AAAAAAAA AAAAAAAA
...	 4 duplicate line(s) removed.
20003DC0 - 41 41 41 41 41 41 41 41  41 41 41 41 41 41 41 41  : AAAAAAAA AAAAAAAA
20003DD0 - 41 41 41 41 41 41 41 41  41 41 41 41 41 41 41 0A  : AAAAAAAA AAAAAAA.
20003DE0 - 30 34 32 39 39 36 20 42  42 42 42 42 42 42 42 42  : 042996 B BBBBBBBB
20003DF0 - 42 42 42 42 42 42 42 42  42 42 42 42 42 42 42 42  : BBBBBBBB BBBBBBBB
...	 4 duplicate line(s) removed.
20003E40 - 42 42 42 42 42 42 42 42  42 42 42 42 42 42 42 42  : BBBBBBBB BBBBBBBB
20003E50 - 42 42 42 42 42 42 42 42  42 42 42 42 42 42 42 0A  : BBBBBBBB BBBBBBB.
20003E60 - 30 34 32 39 39 36 20 43  43 43 43 43 43 43 43 43  : 042996 C CCCCCCCC
20003E70 - 43 43 43 43 43 43 43 43  43 43 43 43 43 43 43 43  : CCCCCCCC CCCCCCCC
...	 4 duplicate line(s) removed.
20003EC0 - 43 43 43 43 43 43 43 43  43 43 43 43 43 43 43 43  : CCCCCCCC CCCCCCCC
20003ED0 - 43 43 43 43 43 43 43 43  43 43 43 43 43 43 43 0A  : CCCCCCCC CCCCCCC.
20003EE0 - 30 34 32 39 39 36 20 44  44 44 44 44 44 44 44 44  : 042996 D DDDDDDDD
20003EF0 - 44 44 44 44 44 44 44 44  44 44 44 44 44 44 44 44  : DDDDDDDD DDDDDDDD
...	 4 duplicate line(s) removed.
20003F40 - 44 44 44 44 44 44 44 44  44 44 44 44 44 44 44 44  : DDDDDDDD DDDDDDDD
20003F50 - 44 44 44 44 44 44 44 44  44 44 44 44 44 44 44 0A  : DDDDDDDD DDDDDDD.
 UNKWN: 3639
4120l: 959591472 T:41414141 : 41414141 41414141 41414141 41414141 41414141
!!! unexpected/unknown message type:13881 len:959591472 op:16672
LP:29235 CMD: 9802(GET_OBJECT_PROP_DESC)l: 20 T:b : dc44 3000 (NAME)
What is interesting is this is sending my specialized indexed file...

Where Each packet contains 4 lines of 128 bytes so 512 bytes. First one is shorted by 12 characters for header...

Now my bogus code looks for these sequence numbers and prints out when they are out of sequence... i.e. missed a packet.
When I call close, it prints out the last sequence number it received...
So it shows: Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999

But the unknown packet is one of the data packets: with sequnce number: 042996

So now question is: did windows resend that one? Or is there some issues with our usb_mtp.c giving me the previous data? like maybe arm_dcache stuff?
We do call flush_delete...

Now back to debugging
 
Is the debuggable 'Bogus' class presenting the same issue as the 'Real' code would? Seems the issue was noted as ... bad packet at the end.

Very odd all is well with packets 0-42995, then 42996 processes well but gets ghosted to recur again after 42997,8,9 are handled.

Is there any terminating message after 42999 completes? Or just no more transmission?

Like that ghosted x96 buffer was partly flushed to RAM and reloads and gets presented as data from a 'next message'
 
Still have not debugged where this packet is coming from...
Error in usb_mtp.c? So far don't see anything.

Yes the interesting thing is we have allocated 4 RX buffers/transfers. I believe that we received all of the data we expected to:
As we returned an OK: 20309 RESP:2001(RSP:OK)l: 12 T:a

Will play more tomorrow.
 
For the heck of it, I wanted to verify that having LittleFS in my bogus copy sketch was not at all involved in the bogus USB packet received stuff, so am trying a totally random thing and try to use a lighter memory file implementation to hold it...

Was going to hack my own, but remember that Frank has one... So thought I would try it :)

Was not an easy drop in replacement so I did a little hacking... Like, I wanted it to still be able to be called by the code to open the file: /mtpindex.dat ..

So added a couple of methods, to it like:
Code:
#ifdef USE_MEMORY_FS
  if (memfs.begin(MEMFS_SIZE)) {
    Serial.printf("Memory Drive of size: %u initialized\n", MEMFS_SIZE);
Also have begin that you can pass in the buffer.

I then added the code for open with pathname, that if it has a buffer it hands it off to the newly created memory file object...
But I also know that the calling code will also ask to open("/"), so special cased it and have a new root directory object, that gets created in this
case. It also in the case of being called with other name, remembers the File object created, and if you ask the RootDirectory object for next file it will return this one
Only once, unless you call rewind...

Anyway did a test run of copy of the large indexed file to my bogus FS, and no difference still get that stray buffer...

But was a fun exercise: And I can see that my very limited root worked as if in the sketch ask to list files on that FS I see:
Code:
Space Used = 4194304
Filesystem Size = 4194304
/mtpindex.dat                         4194304
Not sure if it will go anywhere... But if anyone wants to take a look: https://github.com/KurtE/MemFile/tree/extend_fs
 
Good news for LittleFS, and another great Frank B tool!

Not so good the stray buffer error still present and elusive in the code.

Is there for sure an incoming message from the host that is behind that? Not sure seeing the debug if an incoming message is showing, And not just the code somehow triggering itself to process a non-event?
 
Good news for LittleFS, and another great Frank B tool!

Not so good the stray buffer error still present and elusive in the code.
MemFile - Yes I was going to do my complete version, but decided to save a few minutes and start off with something that I believe works. May still and allow multiple files, that can have fixed addressed buffers and/or can use malloc/realloc or extmem_alloc... But this was only a test

Another point of reference on the stray buffer... I updated the code on my Ubuntu machine to current stuff...
(Minus the Memory File)...

Brought over the large indexed file:


Code:
220170 RESP:2001(RSP:OK)l: 24 T:44 : 20001 ffffffff 15
LP:220171 CMD: 100d(SEND_OBJECT)l: 12 T:45
MTPD::SendObject: len:22015988
&&DT (0,0) (0,0)
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999
Bogus::close(/T4LargeIndexedTestfile.txt) LPN:42999
 # USB Packets: 42999 total: 962 avg ms: 0 max: 18
 # Write: 10750 total:175 avg ms: 0 max: 1
>>>Total Time: 1152017
SendObject() returned true
221323 RESP:2001(RSP:OK)l: 12 T:45
LP:221324  UNKWN: 3639
20003D60 - 30 34 32 39 39 36 20 41  41 41 41 41 41 41 41 41  : 042996 A AAAAAAAA
20003D70 - 41 41 41 41 41 41 41 41  41 41 41 41 41 41 41 41  : AAAAAAAA AAAAAAAA
...	 4 duplicate line(s) removed.
20003DC0 - 41 41 41 41 41 41 41 41  41 41 41 41 41 41 41 41  : AAAAAAAA AAAAAAAA
20003DD0 - 41 41 41 41 41 41 41 41  41 41 41 41 41 41 41 0A  : AAAAAAAA AAAAAAA.
20003DE0 - 30 34 32 39 39 36 20 42  42 42 42 42 42 42 42 42  : 042996 B BBBBBBBB
20003DF0 - 42 42 42 42 42 42 42 42  42 42 42 42 42 42 42 42  : BBBBBBBB BBBBBBBB
...	 4 duplicate line(s) removed.
20003E40 - 42 42 42 42 42 42 42 42  42 42 42 42 42 42 42 42  : BBBBBBBB BBBBBBBB
20003E50 - 42 42 42 42 42 42 42 42  42 42 42 42 42 42 42 0A  : BBBBBBBB BBBBBBB.
20003E60 - 30 34 32 39 39 36 20 43  43 43 43 43 43 43 43 43  : 042996 C CCCCCCCC
20003E70 - 43 43 43 43 43 43 43 43  43 43 43 43 43 43 43 43  : CCCCCCCC CCCCCCCC
...	 4 duplicate line(s) removed.
20003EC0 - 43 43 43 43 43 43 43 43  43 43 43 43 43 43 43 43  : CCCCCCCC CCCCCCCC
20003ED0 - 43 43 43 43 43 43 43 43  43 43 43 43 43 43 43 0A  : CCCCCCCC CCCCCCC.
20003EE0 - 30 34 32 39 39 36 20 44  44 44 44 44 44 44 44 44  : 042996 D DDDDDDDD
20003EF0 - 44 44 44 44 44 44 44 44  44 44 44 44 44 44 44 44  : DDDDDDDD DDDDDDDD
...	 4 duplicate line(s) removed.
20003F40 - 44 44 44 44 44 44 44 44  44 44 44 44 44 44 44 44  : DDDDDDDD DDDDDDDD
20003F50 - 44 44 44 44 44 44 44 44  44 44 44 44 44 44 44 0A  : DDDDDDDD DDDDDDD.
 UNKWN: 3639
4120l: 959591472 T:41414141 : 41414141 41414141 41414141 41414141 41414141
!!! unexpected/unknown message type:13881 len:959591472 op:16672
LP:221328 CMD: 1008(GET_OBJECT_INFO)l: 16 T:46 : 15
221328 RESP:2001(RSP:OK)l: 16 T:46 : 15
LP:221329 CMD: 9801(GET_OBJECT_PROPS_SUPPORTED)l: 16 T:47 : 3000
221329 RESP:2001(RSP:OK)l: 16 T:47 : 3000

So if I see the same stray buffer from both Windows 10 and Ubuntu, my guess is it is something
in our code...
 
@KurtE

Glancing at recent changes ... move to [4] buffers from [2]

If the code went back to [2] buffers, does/did it work then?

Is there a reason this is hardcoded to [0] and [1]? This is 'sendPacket()' - but wonder if maybe some edits missing for [2] to [4]???
Code:
  // ...\libraries\USBHost_t36\src\hid.cpp
bool USBHIDParser::sendPacket(const uint8_t *buffer, int cb) {
	if (!out_size || !out_pipe) return false;	
[B]	if (!_tx[0]) {[/B]
		// Was not init before, for now lets put it at end of descriptor
		// TODO: should verify that either don't exceed overlap descsize
		//       Or that we have taken over this device
[B]		_tx[0] = _bigBufferEnd - out_size;
		_tx[1] = _tx[0] - out_size;
		_bigBufferEnd = _tx[1];[/B]
		_tx_mask = 3;
	}
...

Too many moving parts to understand at a glance ... just wondering ... hoping to strike a chord
 
@KurtE

Glancing at recent changes ... move to [4] buffers from [2]

If the code went back to [2] buffers, does/did it work then?

Is there a reason this is hardcoded to [0] and [1]? This is 'sendPacket()' - but wonder if maybe some edits missing for [2] to [4]???

Too many moving parts to understand at a glance ... just wondering ... hoping to strike a chord
Thanks @defragster,

By default most all HID objects do not provide their own buffers to a Head parser. So by default same behavior as before.
The code was setup for the RAWHID stuff, which tells the the HIDParser, I have more space for parsers... If the parser does not do this, it default back to just two buffers...

What work? If talking about the MTP strange message sometimes. This is happening on the other USB object not the USBHost object. And MTP is not a HID object.
So should not impact.
 
...
What work? If talking about the MTP strange message sometimes. This is happening on the other USB object not the USBHost object. And MTP is not a HID object.
So should not impact.

As I looked before posting I did note in the case of the [0]&[1] hardcoding that setBuffer code was HID specific ...

Had to ask to be sure - to much to catch up on in a few minutes - the buffer count change would have been a nice answer/fix ... so no help there.

Having it across other USB objects indeed indicates it isn't a HID specific change.
 
Back
Top