jborean93 / smbprotocol

Python SMBv2 and v3 Client
MIT License
318 stars 73 forks source link

STATUS_INVALID_PARAMETER: 0xc000000d #165

Closed RalfKraemer1 closed 2 years ago

RalfKraemer1 commented 2 years ago

Hi, I am using a programme to store readings on an OpenMediavault 5 Nas. This worked great for a long time. After updating the NAS, I now get an "unhandled smbprotocol.exceptions.InvalidParameter" error on access.

I have created a log file with this short code. A connection to other devices works.

import smbclient import logging

file_log = logging.FileHandler('smb.log') file_log.setLevel(logging.DEBUG) file_log.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(message)s'))

logger = logging.getLogger() logger.setLevel(logging.DEBUG) logger.addHandler(file_log)

smbclient.ClientConfig(username="user", password="password") smbclient.register_session("nas", username="user", password="password") for filename in smbclient.lscandir(r"\nas\data"): print(filename)

Is there something wrong with the authentication there? With ntlm as authentication it doesn't work either?

smb.log )

Thanks for Helping!

jborean93 commented 2 years ago

Based on your logs and description the connection is failing even before it gets to the authentication attempt. The client is sending the SMB Negotiate request but the server is immediately responding with an invalid parameter failure indicating it failed to process the negotiate request. I'm unfamiliar with OpenMediaVault but having a brief read online indicates it uses SAMBA for the SMB server side. This repo uses SAMBA as part of the CI integration tests https://github.com/jborean93/smbprotocol/blob/master/build_helpers/samba-setup.sh on Linux and I know that is passed just fine.

If you can share the exact version of OpenMediaVault that you are using I'm happy to try and set up a test environment to play with it. The only other thing you can do is to try and enable server side logging to figure out why it's rejecting the negotiate request. Right now it's saying there was an invalid parameter but the error codes are very vague and it doesn't convey what parameter was the actual problem here.

RalfKraemer1 commented 2 years ago

Hello thanks for the quick reply! , OMV uses Samba Version 4.9.5-Debian. Linux server 5.10.0-0.bpo.9-amd64 #1 SMP Debian 5.10.70-1~bpo10+1 (2021-10-10) x86_64 GNU/Linux, Openmedialvault 5.6.25-1.

and the Log File: [2022/03/03 14:53:06.163799, 0] ../lib/tdb_wrap/tdb_wrap.c:64(tdb_wrap_log) tdb(/var/cache/samba/gencache.tdb): tdb_expand overflow detected current map_size[4294967295] size[104]! [2022/03/03 14:53:40.411828, 6, pid=6198, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2338(lp_file_list_changed) lp_file_list_changed() file /etc/samba/smb.conf.client-%I -> /etc/samba/smb.conf.client-192.168.1.21 last mod_time: Thu Mar 3 14:36:47 2022

file /etc/samba/smb.conf -> /etc/samba/smb.conf last mod_time: Thu Mar 3 14:49:07 2022

[2022/03/03 14:53:40.411961, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled [2022/03/03 14:54:40.472123, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2022/03/03 14:54:40.472261, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2022/03/03 14:54:40.472329, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2022/03/03 14:54:40.472376, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2022/03/03 14:54:40.472421, 4, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2022/03/03 14:54:40.472464, 5, pid=6198, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2022/03/03 14:54:40.472505, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:866(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2022/03/03 14:54:40.472591, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:509(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2022/03/03 14:54:40.472644, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled [2022/03/03 14:55:40.475097, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2022/03/03 14:55:40.475368, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2022/03/03 14:55:40.475452, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2022/03/03 14:55:40.475501, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2022/03/03 14:55:40.475547, 4, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2022/03/03 14:55:40.475589, 5, pid=6198, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2022/03/03 14:55:40.475626, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:866(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2022/03/03 14:55:40.475711, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:509(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2022/03/03 14:55:40.475762, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled [2022/03/03 14:56:40.527089, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2022/03/03 14:56:40.527259, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2022/03/03 14:56:40.527330, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2022/03/03 14:56:40.527376, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2022/03/03 14:56:40.527418, 4, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2022/03/03 14:56:40.527459, 5, pid=6198, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2022/03/03 14:56:40.527495, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:866(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2022/03/03 14:56:40.527570, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:509(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2022/03/03 14:56:40.527691, 6, pid=6198, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2338(lp_file_list_changed) lp_file_list_changed() file /etc/samba/smb.conf.client-%I -> /etc/samba/smb.conf.client-192.168.1.21 last mod_time: Thu Mar 3 14:36:47 2022

file /etc/samba/smb.conf -> /etc/samba/smb.conf last mod_time: Thu Mar 3 14:49:07 2022

[2022/03/03 14:56:40.527803, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled [2022/03/03 14:57:40.535082, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2022/03/03 14:57:40.535216, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2022/03/03 14:57:40.535287, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2022/03/03 14:57:40.535335, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2022/03/03 14:57:40.535381, 4, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2022/03/03 14:57:40.535427, 5, pid=6198, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2022/03/03 14:57:40.535469, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:866(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2022/03/03 14:57:40.535553, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:509(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2022/03/03 14:57:40.535604, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled [2022/03/03 14:58:40.567088, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2022/03/03 14:58:40.567223, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2022/03/03 14:58:40.567290, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2022/03/03 14:58:40.567336, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2022/03/03 14:58:40.567414, 4, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2022/03/03 14:58:40.567458, 5, pid=6198, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2022/03/03 14:58:40.567495, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:866(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2022/03/03 14:58:40.567570, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:509(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2022/03/03 14:58:40.567620, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled [2022/03/03 14:59:40.627738, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2022/03/03 14:59:40.627786, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2022/03/03 14:59:40.627803, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:43(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2022/03/03 14:59:40.627811, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2022/03/03 14:59:40.627821, 4, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2022/03/03 14:59:40.627830, 5, pid=6198, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2022/03/03 14:59:40.627839, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:866(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2022/03/03 14:59:40.627860, 5, pid=6198, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:509(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2022/03/03 14:59:40.627898, 6, pid=6198, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2338(lp_file_list_changed) lp_file_list_changed() file /etc/samba/smb.conf.client-%I -> /etc/samba/smb.conf.client-192.168.1.21 last mod_time: Thu Mar 3 14:36:47 2022

file /etc/samba/smb.conf -> /etc/samba/smb.conf last mod_time: Thu Mar 3 14:49:07 2022

[2022/03/03 14:59:40.627927, 10, pid=6198, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:54(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled

jborean93 commented 2 years ago

Thanks for the info, nothing is jumping out in the logs so I'll have to find some time to replicate your setup and test it out.

RalfKraemer1 commented 2 years ago

Hello, is there anything what i can do to Help you? Thanks a lot

Ralf

jborean93 commented 2 years ago

I've just installed OpenMediaVault 5.6.13-1 and cannot replicate the problem. I also installed the latest updates to bring it to 5.6.26-1 and still no luck. I've verified that the version of Samba that is being run is at version 4.9.5 just like your setup.

Accessing the share works just fine and the console shows the active session

>>> import smbclient
>>> smbclient.listdir(r'\\192.168.122.12\my_share', username='smbuser', password='smbpass')
['my_file.txt', 'testing']

image

I'm honestly have no idea why your setup isn't working, it's failing with the first SMB packet the Negotiate message. This message is essentially the client telling the server what features it supports and there is no encryption, signing, or authentication being done at this phase.

At this point there's not much else I can do to try and fix the problem. My only recommendation is to see if you can increase the log level for Samba and see if anything else appears in the logs when trying to connect to the host. I would also try and verify whether other clients can connect to the share. Bare in mind smbprotocol/smbclient uses some fairly new features that have only been introduced with Server 2022/Windows 11 so if you have those on hand it would be good to test them out.

ghost commented 2 years ago

I'm having a very similar problem when connecting using the low level API and specifiying the protocol version. The following at least connects, but file upload using smbclient.shutil.copy is extremly slow:

    import smbclient
    from smbprotocol import Dialects
    from smbprotocol.connection import Connection   

    connection = Connection(uuid.uuid4(), "myserver.com", 445)
    connection.connect(Dialects.SMB_3_0_2)
    connection_cache = {"myserver.com:445": connection}

    smbclient.register_session(
       "myserver.com",
        username="myuser",
        password="mypassword",
        connection_cache=connection_cache
    )

Would be great if there was an option to specify protocol version on the high level client directly. Also I wonder what could cause the extremely slow speed of just a few kilobytes per second.

ghost commented 2 years ago

copy speed can be greatly increased by increasing the buffer size, e.g.: smbclient.shutil.copyfile(local_file, remote_file, connection_cache=connection_cache, buffering=65536 * 128)

jborean93 commented 2 years ago

Closing as this is not something I can replicate after trying the same versions as OP. Without seeing more info from the Samba side as to why it's rejected the Negotiate message there's not much else I can do.

As for exposing the dialect option on the high level API I'm not a fan of this. The client shouldn't care about what dialect it offers and should always try and offer the latest available. If there is a performance issue with using a newer dialect then that should be investigated separately.