Built in SMBfunctionality over-polls

Hi,
one cannot read the article you link to without an account. Please provide more details.
 
Could you provide more logs/details? Maybe the connection behavior on the Proxmox VE side can be improved, but if TrueNAS crashes just because of frequent connections, the issue is still on their side IMHO.
 
fiona said:
Could you provide more logs/details? Maybe the connection behavior on the Proxmox VE side can be improved, but if TrueNAS crashes just because of frequent connections, the issue is still on their side IMHO.
Click to expand...
you're right, and that is just a (late night) guess without evidence on my part, but they could not diagnose because there's an entry in the syslog from proxmox connecting every 10 seconds, which causes the systemd journal to roll over frequently. so.. it is compounding issues. especially since there isn't any way of adjusting the polling interval or turning it off without a hacky cron script.
this is what the log was chock full of:
Code: 
Feb 24 22:10:04 StorMax TNAUDIT_SMB[2871584]: @cee:{"TNAUDIT": {"aid": "f14d02e6-eaf1-486e-992c-0a3e427e3ef5>
Feb 24 22:10:14 StorMax TNAUDIT_SMB[2871881]: @cee:{"TNAUDIT": {"aid": "3fd78f9b-cab3-4014-88d6-02b635d3716b>
Feb 24 22:10:24 StorMax TNAUDIT_SMB[2872180]: @cee:{"TNAUDIT": {"aid": "499921f7-af53-4c6f-883f-9ebdba629de4>
Feb 24 22:10:35 StorMax TNAUDIT_SMB[2872482]: @cee:{"TNAUDIT": {"aid": "de34d833-8b1e-4bcb-bd0c-f80ad00b7d3d>
Feb 24 22:10:44 StorMax TNAUDIT_SMB[2872776]: @cee:{"TNAUDIT": {"aid": "7a026236-da0e-497f-a6ac-812e6fc4efce>
Feb 24 22:10:54 StorMax TNAUDIT_SMB[2873087]: @cee:{"TNAUDIT": {"aid": "c554f007-7d60-4efc-a49d-44cbda473f66>
Feb 24 22:11:04 StorMax TNAUDIT_SMB[2873389]: @cee:{"TNAUDIT": {"aid": "6995bc03-8aa6-4f72-8869-9129460caa60>
Feb 24 22:11:15 StorMax TNAUDIT_SMB[2873691]: @cee:{"TNAUDIT": {"aid": "0df4d9b3-b5df-4a4c-a193-ba2d71c5d365>
Feb 24 22:11:24 StorMax TNAUDIT_SMB[2873984]: @cee:{"TNAUDIT": {"aid": "904bce87-ac62-4485-8d90-a0d721e7c313>
Feb 24 22:11:34 StorMax TNAUDIT_SMB[2874281]: @cee:{"TNAUDIT": {"aid": "a92befb3-5e38-4117-b122-3a9324abe328>
Feb 24 22:11:44 StorMax TNAUDIT_SMB[2874573]: @cee:{"TNAUDIT": {"aid": "2dcbd4f9-d28f-47c7-8981-05e76b3a0f80>
Feb 24 22:11:55 StorMax TNAUDIT_SMB[2874887]: @cee:{"TNAUDIT": {"aid": "8e9c3992-2c63-42db-9249-5c91ace2044b>
Feb 24 22:12:04 StorMax TNAUDIT_SMB[2875180]: @cee:{"TNAUDIT": {"aid": "78783975-060b-4c99-b3c6-56019d341bde>
Feb 24 22:12:14 StorMax TNAUDIT_SMB[2875476]: @cee:{"TNAUDIT": {"aid": "28b50990-26ab-4419-8793-9dc0b4fd39ed>
Feb 24 22:12:24 StorMax TNAUDIT_SMB[2875771]: @cee:{"TNAUDIT": {"aid": "1fa15a3a-09f7-4bbd-bb3f-85222a9a4fbd>
Feb 24 22:12:35 StorMax TNAUDIT_SMB[2876075]: @cee:{"TNAUDIT": {"aid": "8b0f4aa7-e26c-4dea-8f5f-85cf8fc50491>
Feb 24 22:12:44 StorMax TNAUDIT_SMB[2876366]: @cee:{"TNAUDIT": {"aid": "9de3f474-6ac6-4da0-bb48-e05f50bc3978>
Feb 24 22:12:54 StorMax TNAUDIT_SMB[2876676]: @cee:{"TNAUDIT": {"aid": "40d38aa7-ee53-44d3-9a7b-1275ba3f1263>
Feb 24 22:13:04 StorMax TNAUDIT_SMB[2876973]: @cee:{"TNAUDIT": {"aid": "730a0f0c-0559-4106-92f6-dedba6fce53f>
Feb 24 22:13:15 StorMax TNAUDIT_SMB[2877275]: @cee:{"TNAUDIT": {"aid": "1d7e009d-44c3-4931-8ad1-fdb496ad82ea>
Feb 24 22:13:24 StorMax TNAUDIT_SMB[2877565]: @cee:{"TNAUDIT": {"aid": "d37c6680-336a-4fb5-872a-bd854ed9b718>
Feb 24 22:13:34 StorMax TNAUDIT_SMB[2877863]: @cee:{"TNAUDIT": {"aid": "5198d88e-410c-4ee6-8907-ff20d492b1b8>
Feb 24 22:13:44 StorMax TNAUDIT_SMB[2878161]: @cee:{"TNAUDIT": {"aid": "07489bd0-2214-477d-b783-b8392e3df226>
just absolutely solid.
as it is, i've moved the one CIFS share on my PVE instance to NFS, which means no spam.
 
Commissar0617 said:
you're right, and that is just a (late night) guess without evidence on my part, but they could not diagnose because there's an entry in the syslog from proxmox connecting every 10 seconds, which causes the systemd journal to roll over frequently.
so.. it is compounding issues. especially since there isn't any way of adjusting the polling interval or turning it off without a hacky cron script.
this is what the log was chock full of:
Code: 
Feb 24 22:10:04 StorMax TNAUDIT_SMB[2871584]: @cee:{"TNAUDIT": {"aid": "f14d02e6-eaf1-486e-992c-0a3e427e3ef5>
Feb 24 22:10:14 StorMax TNAUDIT_SMB[2871881]: @cee:{"TNAUDIT": {"aid": "3fd78f9b-cab3-4014-88d6-02b635d3716b>
Feb 24 22:10:24 StorMax TNAUDIT_SMB[2872180]: @cee:{"TNAUDIT": {"aid": "499921f7-af53-4c6f-883f-9ebdba629de4>
Feb 24 22:10:35 StorMax TNAUDIT_SMB[2872482]: @cee:{"TNAUDIT": {"aid": "de34d833-8b1e-4bcb-bd0c-f80ad00b7d3d>
Feb 24 22:10:44 StorMax TNAUDIT_SMB[2872776]: @cee:{"TNAUDIT": {"aid": "7a026236-da0e-497f-a6ac-812e6fc4efce>
Feb 24 22:10:54 StorMax TNAUDIT_SMB[2873087]: @cee:{"TNAUDIT": {"aid": "c554f007-7d60-4efc-a49d-44cbda473f66>
Feb 24 22:11:04 StorMax TNAUDIT_SMB[2873389]: @cee:{"TNAUDIT": {"aid": "6995bc03-8aa6-4f72-8869-9129460caa60>
Feb 24 22:11:15 StorMax TNAUDIT_SMB[2873691]: @cee:{"TNAUDIT": {"aid": "0df4d9b3-b5df-4a4c-a193-ba2d71c5d365>
Feb 24 22:11:24 StorMax TNAUDIT_SMB[2873984]: @cee:{"TNAUDIT": {"aid": "904bce87-ac62-4485-8d90-a0d721e7c313>
Feb 24 22:11:34 StorMax TNAUDIT_SMB[2874281]: @cee:{"TNAUDIT": {"aid": "a92befb3-5e38-4117-b122-3a9324abe328>
Feb 24 22:11:44 StorMax TNAUDIT_SMB[2874573]: @cee:{"TNAUDIT": {"aid": "2dcbd4f9-d28f-47c7-8981-05e76b3a0f80>
Feb 24 22:11:55 StorMax TNAUDIT_SMB[2874887]: @cee:{"TNAUDIT": {"aid": "8e9c3992-2c63-42db-9249-5c91ace2044b>
Feb 24 22:12:04 StorMax TNAUDIT_SMB[2875180]: @cee:{"TNAUDIT": {"aid": "78783975-060b-4c99-b3c6-56019d341bde>
Feb 24 22:12:14 StorMax TNAUDIT_SMB[2875476]: @cee:{"TNAUDIT": {"aid": "28b50990-26ab-4419-8793-9dc0b4fd39ed>
Feb 24 22:12:24 StorMax TNAUDIT_SMB[2875771]: @cee:{"TNAUDIT": {"aid": "1fa15a3a-09f7-4bbd-bb3f-85222a9a4fbd>
Feb 24 22:12:35 StorMax TNAUDIT_SMB[2876075]: @cee:{"TNAUDIT": {"aid": "8b0f4aa7-e26c-4dea-8f5f-85cf8fc50491>
Feb 24 22:12:44 StorMax TNAUDIT_SMB[2876366]: @cee:{"TNAUDIT": {"aid": "9de3f474-6ac6-4da0-bb48-e05f50bc3978>
Feb 24 22:12:54 StorMax TNAUDIT_SMB[2876676]: @cee:{"TNAUDIT": {"aid": "40d38aa7-ee53-44d3-9a7b-1275ba3f1263>
Feb 24 22:13:04 StorMax TNAUDIT_SMB[2876973]: @cee:{"TNAUDIT": {"aid": "730a0f0c-0559-4106-92f6-dedba6fce53f>
Feb 24 22:13:15 StorMax TNAUDIT_SMB[2877275]: @cee:{"TNAUDIT": {"aid": "1d7e009d-44c3-4931-8ad1-fdb496ad82ea>
Feb 24 22:13:24 StorMax TNAUDIT_SMB[2877565]: @cee:{"TNAUDIT": {"aid": "d37c6680-336a-4fb5-872a-bd854ed9b718>
Feb 24 22:13:34 StorMax TNAUDIT_SMB[2877863]: @cee:{"TNAUDIT": {"aid": "5198d88e-410c-4ee6-8907-ff20d492b1b8>
Feb 24 22:13:44 StorMax TNAUDIT_SMB[2878161]: @cee:{"TNAUDIT": {"aid": "07489bd0-2214-477d-b783-b8392e3df226>
just absolutely solid.
as it is, i've moved the one CIFS share on my PVE instance to NFS, which means no spam.
Click to expand...
You could just filter out those messages when querying the journal? Or maybe you can configure your logging on the target side differently.

The storage status is queried once every 10 seconds. I suppose maybe the connection could be keept alive/cached, feel free to open a feature request on the bug tracker, but it certainly shouldn't be something a server cannot handle.
 
That is the reason why I stopped using (Samba) shares, provided by TrueNAS, on PVE too...
Getting 8.640 entries per day respectively 259.200 entries per month per PVE-node in the audit log of TrueNAS is unpleasant, to say the least...
 
fiona said:
You could just filter out those messages when querying the journal? Or maybe you can configure your logging on the target side differently.

The storage status is queried once every 10 seconds. I suppose maybe the connection could be keept alive/cached, feel free to open a feature request on the bug tracker, but it certainly shouldn't be something a server cannot handle.
Click to expand...
This is also an issue with zfs over iscsi. My Truenas Scale logs are full of authentication messages making it difficult to see any other issues. It seems that both Proxmox and Truenas aren't interested in acknowledging it as an issue. My assumption is that there isn't a setting to configure the poll frequency. It seems as though Truenas isn't interested in letting us filter the messages either. So we have a standoff.

https://forums.truenas.com/t/truenas-scale-filling-smb-audit-logs/6181/31

Pages and pages of this:

Code: 
Mar 19 20:38:43 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8533 of 11377 items, 6553600 file size, 768 bytes per hash table item), suggesting rotation.
Mar 19 20:38:43 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 19 23:09:43 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8534 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 19 23:09:43 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 01:38:14 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8533 of 11377 items, 6553600 file size, 768 bytes per hash table item), suggesting rotation.
Mar 20 01:38:14 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 04:02:44 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8537 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 20 04:02:44 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 06:34:14 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8534 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 20 06:34:14 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 09:05:14 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8533 of 11377 items, 6553600 file size, 768 bytes per hash table item), suggesting rotation.
Mar 20 09:05:14 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 11:35:25 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8534 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 20 11:35:25 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
 
Last edited:
boomshankerx said:
It seems that both Proxmox and Truenas aren't interested in acknowledging it as an issue.
Click to expand...
fiona said:
I suppose maybe the connection could be keept alive/cached, feel free to open a feature request on the bug tracker, but it certainly shouldn't be something a server cannot handle.
Click to expand...
I did acknowledge the issue and suggested what you can do to increase the chances of somebody looking at it (in the future).
 
Yeah just posted here, in my case is a TrueNAS system.

Loads of hassle to register on that bug report page, only for it to say its locked out, looks like TrueNAS dont want bug reports public, so if anyone can copy and paste it all, would be nice.

C

Post in thread 'NAS constantly active after setting up SMB share in Proxmox'

In my case, I noticed the issue from a huge increase in logging activity on the NAS, every request from proxmox is a new authentication and logged. It isnt affecting sleep on the drives however, they have stayed spun down I assume due to ZFS caching taking care of things, so in my case I might just reconfigure the logging, but I do think proxmox polling every 10 seconds on remote storage is really excessive. It seems to only grab storage utilisation so I think once a minute or even a configurable value should be the way forward, it doesnt need to be this frequent.

Update, seems the...
 
Last edited:
fiona said:
Could you provide more logs/details? Maybe the connection behavior on the Proxmox VE side can be improved, but if TrueNAS crashes just because of frequent connections, the issue is still on their side IMHO.
Click to expand...
It sounds like you not using keepalive from the screenshot.

I notice as an example accessing SMB over my lan is no new authentication request, but on PVE is there every 10 seconds (for each instance of PVE).

Please if you can provide some info on how PVE is doing the polling, then I might be able to see if it can be done without a reauth. I have found the mount point, but not the bit thats doing the polling, might be part of the atop process?
 
Last edited:
boomshankerx said:
This is also an issue with zfs over iscsi. My Truenas Scale logs are full of authentication messages making it difficult to see any other issues. It seems that both Proxmox and Truenas aren't interested in acknowledging it as an issue. My assumption is that there isn't a setting to configure the poll frequency. It seems as though Truenas isn't interested in letting us filter the messages either. So we have a standoff.

https://forums.truenas.com/t/truenas-scale-filling-smb-audit-logs/6181/31

Pages and pages of this:

Code: 
Mar 19 20:38:43 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8533 of 11377 items, 6553600 file size, 768 bytes per hash table item), suggesting rotation.
Mar 19 20:38:43 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 19 23:09:43 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8534 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 19 23:09:43 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 01:38:14 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8533 of 11377 items, 6553600 file size, 768 bytes per hash table item), suggesting rotation.
Mar 20 01:38:14 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 04:02:44 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8537 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 20 04:02:44 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 06:34:14 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8534 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 20 06:34:14 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 09:05:14 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8533 of 11377 items, 6553600 file size, 768 bytes per hash table item), suggesting rotation.
Mar 20 09:05:14 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Mar 20 11:35:25 nas systemd-journald[710]: Data hash table of /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal has a fill level at 75.0 (8534 of 11377 items, 6553600 file size, 767 bytes per hash table item), suggesting rotation.
Mar 20 11:35:25 nas systemd-journald[710]: /var/log/journal/41b709d33bd84b5781e0dbebfc8542bc/system.journal: Journal header limits reached or header out-of-date, rotating.
Click to expand...
I noticed TrueNAS core doesnt have any auth log settings, I manually patched the middleware to disable successful auth logging, which isnt ideal but stops the spam, however I was then surprised to see it only reduced all the i/o by about 20%, so there is something else triggering the writes on boot drive when proxmox has the storage mounted.

Difficult to debug as FreeBSD seems to have inadequate tools to monitor i/o on a per file basis. I cant see anything else being written to in logs. the zfs io stat shows boot pool writing 1.76megabytes every time proxmox polls. Although other data shows it at about 13kB/sec.

Proxmox side could make the 10s a tunable value, or even disable the monitoring altogether, only instead applying a check when the storage is being accessed.
 
Last edited:
You must log in or register to reply here.
Top Bottom