[registrar] can be crashed by running multiple instances of mimeset

[samui]

reproducable bug. click on a video a gazillion times and see what happens.

sometimes you get and out of memory error, sometimes a bad port id error. both of these errors randomly crash deskbar and or tracker. the mouse freezes.

Sometimes you are dropped to kdl with the enclosed info.

256mb of ram, no virtual memory enabled, build 38817

[stippi]

When you say "click on a video a gazillion times", you mean double click it in Tracker, right? Do you leave each instance open, or do you close it each time before you open it again? Since one of my changes to the media node based playback in MediaPlayer, the video producer node and the video consumer node share the same video buffers (to avoid having to copy a video frame when it is transfered from the producer to the consumer node). Upon destruction of the connection, the media_server failes to deallocate these buffers. I have not investigated this issue closer for the time being. Just a hint in case I don't get around to fixing that, for whoever wants to work on it later.

[stargatefan]

I was wondering if maybe that was the issue with gnash. Buffer deallocation.

[diver]

I can reproduce this bug easily on real hardware by opening /boot/common/boot/post_install, selecting mime_update.sh and holding down the return key for about 30 seconds. Most of the time registar crashes in create_app_meta_mime thread or in main_mime thread (MIMEManager::MessageReceived). Sometimes it KDLs (see attached images). I tried to find a shorter way to reproduce this bug, but behavior has changed:

for i in `seq 1 10000`; do mimeset -apps -f /system/apps/*; done"

After running this command (in vbox, so take with a grain of salt) simultaneously in several tabs registrar just dies silently and launching new apps throws Bad port ID error (sounds a lot like #381).

[diver]

After getting Bad port ID error Tracker crashed. I tried to find it in syslog after reboot and found something, but I'm not sure if it's really the tracker crash traces, but anyway:

KERN: 16665: DEBUGGER: The clipboard must be locked before proceeding.
KERN: debug_server: Thread 16665 entered the debugger: Debugger call: `The clipboard must be locked before proceeding.'
KERN: stack trace, current PC 0xffff0114  :
KERN:   (0x782068bc)  0x2c5821  _ZNK10BClipboard13_AssertLockedEv + 0x39
KERN:   (0x782068dc)  0x2c5849  _ZNK10BClipboard4DataEv + 0x1d
KERN:   (0x782068fc)  0x518b64  _Z23FSClipboardFindNodeModePN8BPrivate5ModelEbb + 0x6c
KERN:   (0x782069dc)  0x57d3e0  _ZN8BPrivate9BPoseView11CreatePosesEPPNS_5ModelEPNS_8PoseInfoElPPNS_5BPoseEbPlP5BRectb + 0x814
KERN:   (0x78206b3c)  0x5891a6  _ZN8BPrivate9BPoseView15MessageReceivedEP8BMessage + 0x386
KERN:   (0x78206c3c)  0x2caa38  _ZN7BLooper15DispatchMessageEP8BMessageP8BHandler + 0x50
KERN:   (0x78206c5c)  0x38e404  _ZN7BWindow15DispatchMessageEP8BMessageP8BHandler + 0x19da
KERN:   (0x78206f1c)  0x389d09  _ZN7BWindow11task_looperEv + 0x22b
KERN:   (0x78206f9c)  0x2cc29a  _ZN7BLooper7_task0_EPv + 0x30
KERN:   (0x78206fbc)  0x66518d  thread_entry + 0x2d

[diver]

Could it be that MediaPlayer registers mime types on every start? Then it could explain observed behavior from the description with regard to registrar.

[bonefish]

The KDL is tracked in #5474.

Regarding the Tracker crash, that's due to BPoseView::CreatePoses() not checking the return value of be_clipboard->Lock(), just assuming it worked. Since BClipboard::Lock() does synchronous messenging, which might require a port to be created on the fly, running out of ports can cause BClipboard::Lock() to fail.

Why the system is running out of ports is an interesting question, though. The registrar seems to limit the MIME update threads to 12, denying any further requests after the limit is reached. So, at least in theory, there shouldn't be any resources piling up in the registrar due to MIME update requests. The output of a listport (or ports in KDL -- long, so skip and fetch from syslog) in such a situation would at least help to identify who is leaking/hogging what kind of ports.

Why the registrar crashes is another interesting question. One stack trace is an hoard assert, so the heap had been corrupted. The other is an outright crash in MIMEManager::MessageReceived(), though I haven't spotted any suspicious code (the syslog would have been nice). Might also be a side effect of a heap corruption.

What looks a bit suspicious is RegistrarThreadManager. It uses atomic operations to change fThreadCount, but doesn't do any locking to protect the thread list (fThreads). I haven't investigated this further, but so far I've seen the RegistrarThreadManager only being used in the MIMEManagers thread. So the atomic operations might simply be superfluous.

[diver]

Replying to bonefish:

The output of a listport (or ports in KDL -- long, so skip and fetch from syslog) in such a situation would at least help to identify who is leaking/hogging what kind of ports.

My keyboard doesn't work in KDL, I do have auto_stack_trace installed, though. Is there a way to modify it to auto execute listport/ports. Also, how should I enter KDL? Alt-Sysreq-D just prints a small backtrace for keyboard thread and hangs.

[bonefish]

Replying to diver:

Replying to bonefish:

My keyboard doesn't work in KDL, I do have auto_stack_trace installed, though. Is there a way to modify it to auto execute listport/ports. Also, how should I enter KDL? Alt-Sysreq-D just prints a small backtrace for keyboard thread and hangs.

listport is a command line program. I mentioned the KDL alternative only in case listport cannot be executed/doesn't work correctly in this situation.

With a USB keyboard you have to at least once enter KDL via Alt-SysReq-D, since otherwise it won't work. If it doesn't work anyway (e.g. because it's OHCI) you're out of luck. I'm not aware of any method to easily execute other KDL commands automatically. I think auto_stack_trace is mostly superfluous nowadays, as any panic prints a stack trace anyway and when voluntarily entering KDL one usually can (and wants to) do other/more things. auto_stack_trace cannot be configured. If you build your images yourself, you could hack it to execute another command instead of sc, though.

[diver]

I tried to reproduce it several times in hrev42467, but I don't get these crashes anymore. I got new one #7864, though.

[diver]

Tried to reproduce it again (by starting mime_update.sh many times) and got fullscreen GDB once again. Unfortunately, my keyboard didn't work there. I tried to reproduce it one more time after reboot but didn't manage to crash it, instead after some time running process started by mime_update.sh stopped quitting. CPU usage was always at max, there was a lot of free memory, though.

[diver]

Managed to crash it again, this time with ssh access:

KERN: 60: DEBUGGER: getNumAvailable() == 0
KERN: debug_server: Thread 60 entered the debugger: Debugger call: `getNumAvailable() == 0'
KERN: stack trace, current PC 0xffff0114  :
KERN:   (0x700c1b7c)  0x5f1062  __assert_fail + 0x46
KERN:   (0x700c1b9c)  0x665504  _ZN8BPrivate9hoardHeap23findAvailableSuperblockEiRPNS_5blockEPNS_11processHeapE + 0x34c
KERN:   (0x700c1bec)  0x663431  _ZN8BPrivate10threadHeap6mallocEm + 0xa3
KERN:   (0x700c1c3c)  0x663949  malloc + 0x1b5
KERN:   (0x700c1c5c)  0x5ed4bf  _ZN8BPrivate8KMessage14_AllocateSpaceElbbPPvPl + 0x95
KERN:   (0x700c1c9c)  0x5ed64d  _ZN8BPrivate8KMessage9_AddFieldEPKcmlPNS_13KMessageFieldE + 0x3b
KERN:   (0x700c1cec)  0x5ee261  _ZN8BPrivate8KMessage7AddDataEPKcmPKvlb + 0xa5
KERN:   (0x700c1d4c)  0x22567d  _ZN21AuthenticationManager14_RequestThreadEv + 0x11c3
KERN:   (0x700c1f9c)  0x2272db  _ZN21AuthenticationManager19_RequestThreadEntryEPv + 0x1b
KERN:   (0x700c1fbc)  0x5ea957  thread_entry + 0x1d 
KERN: ps2: possibly a hot plugin of input/keyboard/at/0
KERN: ps2: devfs_publish_device input/keyboard/at/0, status = 0x00000000
KERN: ps2: keyboard found

After that I connected ps2 keyboard which didn't work anyway.

[diver]

Running kernel_debugger from ssh made my ps2 keyboard work in KDL, see debug_session attachment.

[diver]

This behavior seems to be related to gcc4 as I'm unable to reproduce these issues under gcc2.

[diver]

registrar still silently crashes in hrev44065 gcc4 while running:

for i in `seq 1 100000`; do mimeset -apps -f /system/apps/*; done

in 6 Terminals simultaneously. debug_server doesn't seem to catch it. Every open terminal starts printing:

FATAL: be_roster is not valid. Is the registrar running?

registrar is easily restartable using on_exit /system/servers/registrar KDL command.

[diver]

hrev47261 gcc2hybrid.

Out of curiosity I tried the above command with a freshly unpacked archive of BeOS apps archive just to see how things are now two years later. Registrar crashed, but this time this was with gcc2 image and I managed to save debug report.

[diver]

(In #11063) Seems to be a dupe of #6673.

[CodeforEvolution]

As of hrev54154+119 on a x86_gcc2 Haiku system, I can't reproduce the registrar crash anymore after stress testing the registrar with up to 30 instances of "for i in seq 1 100000; do mimeset -apps -f /system/apps/*; done" running concurrently.

The only error I notice comes after 8-10 instances of mimeset running concurrently, in which case the Terminal will start printing "mimeset: no more threads", which is less troubling than a crash. After closing the Terminal (which automatically kills all mimeset jobs), everything continues to work as expected: Apps launch, mimetyping works, and no errors are even reported to the syslog. I can even try the stress test again!

Could someone double check on a newer version of the x86_64 version of Haiku? If all is well, I think this commit a while back may have fixed what was going on: ​https://git.haiku-os.org/haiku/commit/?id=462bfeede0cd123afe2e79d465876289e925ca53

[CodeforEvolution]

Upon further analysis of the registrar codebase, the “no more threads” error is an expected behavior/safety mechanism to make sure the registrar isn’t doing too much work at once (the current limit is hard-wired into the registrar at 12 concurrent tasks).

Unless anyone else has any problems, I believe this problem was fixed in hrev49570. Diver’s last test was in hrev47261, so I believe the test results may not longer be a problem.

Thus, I believe this critical ticket can be closed! :)

[nielx]

Replying to CodeforEvolution:

Upon further analysis of the registrar codebase, the “no more threads” error is an expected behavior/safety mechanism to make sure the registrar isn’t doing too much work at once (the current limit is hard-wired into the registrar at 12 concurrent tasks).

Unless anyone else has any problems, I believe this problem was fixed in hrev49570. Diver’s last test was in hrev47261, so I believe the test results may not longer be a problem.

Thus, I believe this critical ticket can be closed! :)

Thanks for testing! Indeed, let's close it.

[madmax]

Sorry to comment just after the ticket has been closed.

I've attached a crash report for hrev54447 x86_64. I guess after so many years it's not the same bug, but it certainly is the same reproducer with the same effects.

Maybe I was just lucky, but I got the crash on real hardware when I was still starting those "mimeset bomb loops", and I couldn't reproduce it in three 15-minute runs in qemu-kvm with different smp settings.

[nielx]

No worries, thanks for posting the stack traces, this will allow us to further investigate the issue.

[CodeforEvolution]

Thank you for the stack trace! I think two threads must of collided...I see a "General protection fault" on one thread, and a "Call (_numAvailable <= _numBlocks)" debugger call on the other thread. They also were doing the exact same thing, using BIconUtils::GetVectorIcon().

I wonder if these two threads collided because they were working on the same file...

[waddlesplash]

The second is a malloc assertion, it sounds like heap corruption.

[madmax]

I tried again after updating in case hrev54529 helped, but still crashed. The stack trace is quite similar this time on getting memory instead of releasing, if I understand it correctly.

I can't debug this myself, but I can apply patches, compile and follow directions. If there's anything I can do to help track this down, just tell me.

[CodeforEvolution]

That really is strange...as waddlesplash mentioned, that really does look like memory corruption of sorts...and once again, it was in BIconUtils::GetVectorIcon...

Anyway, thank you for these logs! These sort of crashes requires all the info we can get! :)

[diver]

cl-amp and ​http://pulkomandy.tk/~beosarchive/unsorted/BDifferent/Emulators/BeSmsPlus0.9.3.zip also trigger this crash.

[X512]

On RISC-V port I see that on each application start and Tracker icon update registrar mime-update thread is created. It may be related.

[madmax]

Fixed somewhere ​between hrev57193 and hrev57197.

[waddlesplash]

That seems surprising to me. If it was a double-lock race, that could have been fixed by some of the earlier commits, but for it to be fixed by one of those changes seems a bit unexpected. But if you've tested thoroughly and it seems to really be the case, well, I guess that's that...

[madmax]

Can't be sure with this kind of bug, but hrev57193 and older quickly trigger either a crash or what looks like a deadlock, some times when I'm still launching the bombs. hrev57197 and current nightly had no issues after running the reproducer for more than half an hour.

[waddlesplash]

Hmm. Could you perhaps try and narrow down precisely which commit in that series fixed the problem? It might be good to get a better understanding of it. If it's just the locking commits that's one thing, but if it's the Queue changes, that might be indicative of something else going on.

[madmax]

​6d30655 kernel/condition_variable: Adjust notified count and wait-status returning rids me of crashes and deadlocks. I've noticed the syslog is spammed with ​libroot __mutex_unlock: mutex was not actually locked! messages while running the mimeset bombs, though.

[waddlesplash]

That's strange. If it had been the commit prior to that one, that would make sense, but for it to be that one is odd.

Could you perhaps enable that debugger() invocation and see where it triggers? If it's inside hoard2 that's one thing, but if it's triggering inside registrar itself that may be the real problem.

[madmax]

Edit: forgot to say these are enabling the debugger on current master

There's a variety of stack traces, all from registrar threads (usually "create_app_meta_mime (s)", but I got one from "messaging command processor"), always with free at the top.

stack trace, current PC 0x1c2360ab099  </boot/system/lib/libroot.so> _kern_debugger + 0x9:
  (0x7f4324e20c10)  0x1c236133169  </boot/system/lib/libroot.so> free + 0x49
  (0x7f4324e20c40)  0x1dd98b00136  </boot/system/lib/libbe.so> _ZN3agg11pod_bvectorINS_11vertex_distELj6EED2Ev + 0x36
  (0x7f4324e20c60)  0x1dd98b01451  </boot/system/lib/libbe.so> _ZN8BPrivate4Icon17StrokeTransformerD0Ev + 0x11
  (0x7f4324e20c80)  0x1dd98afa5d8  </boot/system/lib/libbe.so> _ZN8BPrivate4Icon9ContainerINS0_11TransformerEE9MakeEmptyEv + 0xd8
  (0x7f4324e20d10)  0x1dd98afa140  </boot/system/lib/libbe.so> _ZN8BPrivate4Icon5ShapeD2Ev + 0xb0
  (0x7f4324e20d40)  0x1dd98af94d1  </boot/system/lib/libbe.so> _ZN8BPrivate4Icon15PathSourceShapeD0Ev + 0x11
  (0x7f4324e20d60)  0x1dd98b025f7  </boot/system/lib/libbe.so> _ZN8BPrivate4Icon9ContainerINS0_5ShapeEE9MakeEmptyEv + 0xb7
  (0x7f4324e20df0)  0x1dd98b022d4  </boot/system/lib/libbe.so> _ZN8BPrivate4Icon4IconD2Ev + 0x34
  (0x7f4324e20e20)  0x1dd98af5e3a  </boot/system/lib/libbe.so> _ZN10BIconUtils13GetVectorIconEPKhmP7BBitmap + 0x29a
  (0x7f4324e21280)  0x1dd98aacd60  </boot/system/lib/libbe.so> _ZNK12BAppFileInfo14GetIconForTypeEPKcP7BBitmap9icon_size + 0x340
  (0x7f4324e21330)  0xad7223f5e7  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime18AppMetaMimeCreator2DoERK9entry_refPb + 0x4b7
  (0x7f4324e21640)  0xad7223e674  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread11UpdateEntryEPK9entry_ref.localalias + 0x54
  (0x7f4324e21710)  0xad7223e82d  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread14ThreadFunctionEv + 0xad
  (0x7f4324e217b0)  0x1c2360a9dc9  </boot/system/lib/libroot.so> thread_entry + 0x19

stack trace, current PC 0x441a005099  </boot/system/lib/libroot.so> _kern_debugger + 0x9:
  (0x7f6eec37d750)  0x441a08d169  </boot/system/lib/libroot.so> free + 0x49
  (0x7f6eec37d780)  0x1b4c6ec2c0c  </boot/system/lib/libbe.so> _ZN8BPrivate7Storage12ResourceFile13_InitELFXFileI10Elf64_Ehdr10Elf64_Phdr10Elf64_ShdrEEvR5BFilem + 0x3bc
  (0x7f6eec37d850)  0x1b4c6eac166  </boot/system/lib/libbe.so> _ZN8BPrivate7Storage12ResourceFile12_InitELFFileER5BFile + 0x86
  (0x7f6eec37d8a0)  0x1b4c6ead072  </boot/system/lib/libbe.so> _ZN8BPrivate7Storage12ResourceFile9_InitFileER5BFileb + 0x232
  (0x7f6eec37d930)  0x1b4c6ead0dd  </boot/system/lib/libbe.so> _ZN8BPrivate7Storage12ResourceFile5SetToEP5BFileb + 0x2d
  (0x7f6eec37d970)  0x1b4c6ead8a6  </boot/system/lib/libbe.so> _ZN10BResources5SetToEPK5BFileb + 0xd6
  (0x7f6eec37d9b0)  0x1b4c6e940e6  </boot/system/lib/libbe.so> _ZN12BAppFileInfo5SetToEP5BFile + 0xe6
  (0x7f6eec37d9e0)  0x1b4c6e941ba  </boot/system/lib/libbe.so> _ZN12BAppFileInfoC1EP5BFile + 0x3a
  (0x7f6eec37da00)  0x4629e281ce  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime18AppMetaMimeCreator2DoERK9entry_refPb + 0x9e
  (0x7f6eec37dd10)  0x4629e27674  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread11UpdateEntryEPK9entry_ref.localalias + 0x54
  (0x7f6eec37dde0)  0x4629e276dd  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread11UpdateEntryEPK9entry_ref.localalias + 0xbd
  (0x7f6eec37deb0)  0x4629e276dd  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread11UpdateEntryEPK9entry_ref.localalias + 0xbd
  (0x7f6eec37df80)  0x4629e2782d  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread14ThreadFunctionEv + 0xad
  (0x7f6eec37e020)  0x441a003dc9  </boot/system/lib/libroot.so> thread_entry + 0x19

stack trace, current PC 0x20825b12099  </boot/system/lib/libroot.so> _kern_debugger + 0x9:
  (0x7ffe15231920)  0x20825b9a169  </boot/system/lib/libroot.so> free + 0x49
  (0x7ffe15231950)  0xbf173b5f11  </boot/system/servers/registrar> _ZN16MessageDeliverer14DeliverMessageEPKviR18MessagingTargetSetl + 0x3a1
  (0x7ffe152319d0)  0xbf173b83c6  </boot/system/servers/registrar> _ZN16MessagingService17_CommandProcessorEv + 0xd6
  (0x7ffe15231a30)  0x20825b10dc9  </boot/system/lib/libroot.so> thread_entry + 0x19

stack trace, current PC 0xab414e5099  </boot/system/lib/libroot.so> _kern_debugger + 0x9:
  (0x7fee041ffeb0)  0xab4156d169  </boot/system/lib/libroot.so> free + 0x49
  (0x7fee041ffee0)  0xf1100356d3  </boot/system/lib/libbe.so> _ZN9BMallocIOD2Ev + 0x23
  (0x7fee041fff00)  0x107a56ce280  </boot/system/servers/registrar> _ZN16MessageDeliverer14DeliverMessageEP8BMessageR18MessagingTargetSetl + 0x70
  (0x7fee041fff90)  0x107a56ce2f1  </boot/system/servers/registrar> _ZN16MessageDeliverer14DeliverMessageEP8BMessage10BMessengerl + 0x51
  (0x7fee04200010)  0x107a56d06c4  </boot/system/servers/registrar> _ZN11MIMEManager6NotifyEP8BMessageRK10BMessenger + 0x44
  (0x7fee04200060)  0x107a56e21a2  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime8Database18_SendMonitorUpdateEiPKcbi + 0x112
  (0x7fee04200120)  0x107a56e303b  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime8Database14SetIconForTypeEPKcS4_PKvm + 0x2fb
  (0x7fee042001e0)  0x107a56e0ce1  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime18AppMetaMimeCreator2DoERK9entry_refPb + 0xbb1
  (0x7fee042004f0)  0x107a56df674  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread11UpdateEntryEPK9entry_ref.localalias + 0x54
  (0x7fee042005c0)  0x107a56df82d  </boot/system/servers/registrar> _ZN8BPrivate7Storage4Mime16MimeUpdateThread14ThreadFunctionEv + 0xad
  (0x7fee04200660)  0xab414e3dc9  </boot/system/lib/libroot.so> thread_entry + 0x19

[waddlesplash]

I guess this is an instance of #18451, then. It looks like a more reliable reproducer than anything else we have so far.