LE11 Nightly - Samba server freezes, including logs - NTFS3 KERNEL DRIVER IS SLOW

Hello all!

I run an RPi4 h/w rev 1.5 with LE11 nightly-20220207-72b6d0d (RPi-LE).

Wi-Fi is used to connected to my home network and the internet. The Ethernet port is used for a direct link to another RPi (preferred technology order changed in connman).

It has a 5TB USB3 HDD connected to it with single partition formatted in NTFS, mounted by ntfs3g. That hard drive's partition is shared over Samba. The drive's content is 4K HDR videos with HBR audio, directly connected for performance purposes.

There is another Raspberry Pi (RPi-Mgr), running DietPi, connected to the first using the private Ethernet link, mounting the above shared drive through this link, vers=3.1.1 (tried going down to 2.0 with the same results). This Pi manages the content on the USB hard drive.

Randomly, and quite regularly, RPi-Mgr reports that the mounted network share stops responding, which creates havoc higher up in the software stack.

I have tried using a network mount using SMB from my NAS, using the exact same workflow, with ideal results. So RPi-Mgr can be considered fine.

So I've taken a look at RPi-LE, the Samba server.

I may have been pretty annoying in another post, thinking that the h/w rev and firmware could be problematic, apparently in error... Oooops...

I started turning the smbd logs to level 10 (stupidly verbose) about everything and went about the normal workflow, looking for the time the client reports the server as unresponsive. I then grepped the server smbd logs for that time. Uh oh... No result!

So i went into the file, massively dense logs, and searched for the timestamp. Nada, zilch, zip, rien, nothing! There is a gap in all logs for about 20s! No information appears before or after indicative of any ill reaction. It's as if smbd took a break for an espresso cup and came back, as if nothing was wrong... Nothing weird appears in the journalctl logs about the rest of the system either.

Now, that is annoying... There is something that is clearly happening, but I can't find any verbosity about it.

No data, no help, no fix...

What could I do to generate anything that would be useful?

I have an identical pair of RPis, one running LE11 nightly-20220120-f7f2fd5 on Raspberry Pi 4 Model B Rev 1.2, without any issue at all. That on is in production, so I'm not too tempted to upgrade it. I just wish I had an installable image of that version handy to put on the dev kit as a comparison point.

Nico

Quote from heitbaum

As a note - the Ntfs version being used in nightlies is now ntfs3 - https://github.com/LibreELEC/LibreELEC.tv/pull/5838 - which is the Paragon Kernel version. but it is a different version to the ntfs3g that we and other distributions were using before kernel 5.15.

Sorry! Force of habit...

Quote from HiassofT

Please try to add "debugging" to the end of cmdline.txt, this enables extra debug logging (for connman and other services) which might provide important information. Then upload logs as usual (journalctl should be the most important).

so long,

Hias

It shall be done tomorrow!

Nico

Quote from HiassofT

Please try to add "debugging" to the end of cmdline.txt, this enables extra debug logging (for connman and other services) which might provide important information. Then upload logs as usual (journalctl should be the most important).

so long,

Hias

Doing it now, but, of course, there has been absolutely zero smb drops yet!

I'm now cross-compiling an LE11 nightly-20220120-f7f2fd5 image. Seeing if that one works well or not could be a nice data point.

Ah, crap, I can't... Debian is not hosting http://ftp.debian.org/debian/pool/ma….26.orig.tar.gz anymore...

Darnit!

Quote from HiassofT

Please try to add "debugging" to the end of cmdline.txt, this enables extra debug logging (for connman and other services) which might provide important information. Then upload logs as usual (journalctl should be the most important).

so long,

Hias

Here is the journalctl with the system booted with the debugging option:

http://ix.io/3Pd4

NOT enlightening...

For info, here are the timestamps when the client complained about the share being unavailable:

Feb 10 12:05:07 grabber kernel: CIFS: VFS: \\10.25.25.2 sends on sock 00000000c37af84c stuck for 15 seconds
Feb 10 12:05:07 grabber kernel: CIFS: VFS: \\10.25.25.2 Error -11 sending data on socket to server
Feb 10 12:05:31 grabber kernel: CIFS: VFS: \\10.25.25.2 sends on sock 0000000083fa5a17 stuck for 15 seconds
Feb 10 12:05:31 grabber kernel: CIFS: VFS: \\10.25.25.2 Error -11 sending data on socket to server
Feb 10 12:05:31 grabber kernel: CIFS: VFS: Send error in read = -11
Feb 10 12:05:47 grabber kernel: CIFS: VFS: \\10.25.25.2 sends on sock 0000000083fa5a17 stuck for 15 seconds
Feb 10 12:05:47 grabber kernel: CIFS: VFS: \\10.25.25.2 Error -11 sending data on socket to server



Feb 10 12:06:13 grabber kernel: CIFS: VFS: \\10.25.25.2 sends on sock 0000000024556f67 stuck for 15 seconds
Feb 10 12:06:13 grabber kernel: CIFS: VFS: \\10.25.25.2 Error -11 sending data on socket to server
Feb 10 12:06:26 grabber kernel: CIFS: VFS: Send error in read = -11
Feb 10 12:06:26 grabber kernel: CIFS: VFS: \\10.25.25.2 trying to return 10 credits to old session

What else could I turn on for you that could enable something more useful?

Nico

Quote from HiassofT

Can you test with a simple, stock network configuration? i.e. plain LE installation with just wired (or wifi) network enabled but not both wifi and wired at the same time.

I'm suspecting network / routing could be the culprit, that test should help to narrow it down.

so long,

Hias

Single network, wired, was how it was until very recently, and the problem was exactly the same.

I have changed to that second backend network only once I thought that the new bootloader/firmware/kernel/samba combo had stabilised things, in error, when I thought that I could put the kit in production at my friend's.

Single network or two networks show exactly the same behaviour.

In any case, this is all very simple networking, a directly connected class C on one interface, with the default route, another directly connected class C on another interface. The mount is using the IP address on that directly connected class C network. There is no need for any IP forwarding to be turned on.

Nothing is confusing, the routing table is exactly as it should be, with proper metrics, as is the IP assignment on the interfaces.

kodiplayer:~ # ip rout sh
0.0.0.0 dev eth0 scope link 
default via 192.168.1.1 dev wlan0 
8.8.4.4 dev eth0 scope link 
8.8.8.8 dev eth0 scope link 
10.25.25.0/24 dev eth0 scope link  src 10.25.25.2 
192.168.1.0/24 dev wlan0 scope link  src 192.168.1.136 
192.168.1.1 dev wlan0 scope link 


kodiplayer:~ # ip add sh
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP8000> mtu 1500 qdisc mq qlen 1000
    link/ether e4:5f:01:86:99:96 brd ff:ff:ff:ff:ff:ff
    inet 10.25.25.2/24 brd 10.25.25.255 scope global eth0
       valid_lft forever preferred_lft forever
3: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP8000> mtu 1500 qdisc fq_codel qlen 1000
    link/ether e4:5f:01:86:99:98 brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.136/24 brd 192.168.1.255 scope global wlan0
       valid_lft forever preferred_lft forever

The issue is not network related.

After a while I get smbd becoming unstable and segfaulting.

Still not correlated with the client in the timestamps

http://ix.io/3PeH

Nico

Quote from HiassofT

Code

Feb 10 17:00:10 kodiplayer smbd[6089]:   smb2_sendfile_send_data: sendfile failed for file Transit/Incoming/Game.of.Thrones.S03.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT/Game.of.Thrones.S03E06.The.Climb.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (Connection reset by peer) for client ipv4:10.25.25.1:46624. Terminating

"Connection reset by peer" means the client (i.e. the other machine) unexpectedly closed the connection.

Might be worth looking into what the client is doing and also testing if the issue happens with other clients (eg a Windows box).

so long,

Hias

I would theorise that this is the client resetting things because all hell broke loose at some point, and not the root problem. It is a pretty rare occurrence.

I am, however testing both your and my theories, moving large files back and forth using another client and watching the server's logs.

Just a reminder from another thread, I had tested my client using another Samba server, one running on my old-ish Lenovo-EMC NAS, without any hiccup whatsoever, as I naturally wanted to find out if it was a server or client issue.

Quote from JoeAverage

have you tried to do what is written in the log ?

Code

Feb 10 16:39:35 kodiplayer smbd[5958]:   If you are running a recent Samba version, and if you think this problem is not yet fixed in the latest versions, please consider reporting this bug, see https://wiki.samba.org/index.php/Bug_Reporting

Should I really push that issue upstream now? Is LE using the latest and greatest from Samba? Is the issue really a Samba bug?

I have no problem contacting the Samba guys and following up, but I feel that there is a bit more that needs gathering before that.

Also, LE is using Samba 4.13.17, samba.org announces that the latest stable is 4.15.5. I can't judge the LE decision to use an older version, but there must be a good one. I'm pretty sure that if I contact upstream, the first reaction will be to ask me to use the latest version first and go from there, as mentioned in the log message.

I absolutely hate problems coming up randomly or without an identified...

I've been hammering the system with the usual workflow plus additional external transfers, and not a single drop or anything in the past 24 hours... Aaaaaaaaaaah!

UK morning all!

I have a bit of time to dedicate to this today.

First, I don't believe that I've ever given the client's mount parameters:

//10.25.25.2/content on /mnt/content type cifs (rw,relatime,vers=3.1.1,cache=strict,username=guest,uid=1000,forceuid,gid=1000,forcegid,addr=10.25.25.2,file_mode=0770,dir_mode=0770,soft,nounix,serverino,mapposix,rsize=4194304,wsize=4194304,bsize=1048576,echo_interval=60,actimeo=1,x-systemd.automount)

Who knows why there is an NFS mount option in there (actimeo)...

The server's parameters are default LE, automatically sharing external discs.

The gaps in logs were in the Samba logs with Level 10 on.

Those Samba bugs are not really helpful, but I'm not the best person to judge.

I'll try to coerce the LE samba to do some client-specific logging and come back here with data.

[EDIT] It's on and working, giving very dense/verbose logs. How much you want to bet that the error won't crop up for hours, or at least before the /storage partition of my SD card is full?

Oh, and a last data point, not the smallest: the similar production setup running an LE11 20220120 that I believed not subjected to the issue has displayed the same problem. This is depressing as it removes the possibility of a good known point...