Bug 8311 - Winzip occasionally can not read files out of an open winzip dialog (SMB2 support too incomplete)
Winzip occasionally can not read files out of an open winzip dialog (SMB2 sup...
Status: RESOLVED FIXED
Product: Samba 3.6
Classification: Unclassified
Component: File services
3.6.0rc2
All Windows 7
: P5 normal
: ---
Assigned To: Karolin Seeger
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2011-07-19 14:09 UTC by Eric Solheim
Modified: 2012-06-22 10:35 UTC (History)
5 users (show)

See Also:


Attachments
Logs for opening files inside of winzip showing successful and unsucessful attempts (40.00 KB, application/x-tar)
2011-07-19 14:09 UTC, Eric Solheim
no flags Details
Log attached for a failed delete attempt (30.67 KB, text/plain)
2011-07-19 15:45 UTC, Eric Solheim
no flags Details
SMB Logs for Bug (65.32 KB, application/x-zip-compressed)
2011-07-28 13:42 UTC, Eric Solheim
no flags Details
Install Instructions and smb.conf file (18.55 KB, application/x-zip-compressed)
2011-07-29 15:09 UTC, Eric Solheim
no flags Details
Untested patch for 3.6 (24.21 KB, patch)
2012-05-29 11:55 UTC, Stefan Metzmacher
jra: review-
Details
git-am fix for 3.6.next. (22.74 KB, patch)
2012-06-04 23:03 UTC, Jeremy Allison
metze: review+
jra: review? (rsharpe)
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Eric Solheim 2011-07-19 14:09:22 UTC
Created attachment 6701 [details]
Logs for opening files inside of winzip showing successful and unsucessful attempts

Winzip occasionally fails to read files (or transfer files out) out of an open winzip dialog box.
It appears two different paths are followed for authentication. 
Files attached from the server log with a successful attempt 
and an unsuccessful attempt.

Server is Enterprise Linux using ACL's.
Client is Windows 7 use SMB2

Patches applied from Bug 8219
6643 and 6650
Using SMB2 Signing
Comment 1 Eric Solheim 2011-07-19 15:45:21 UTC
Created attachment 6702 [details]
Log attached for a failed delete attempt

This also seems to cause delete to fail occasionally in the explorer window looking at the log the problems seem related.
Delete provides no error message but the file is still present when refreshing.  File deletes with no error under same user in Linux.
Comment 2 Eric Solheim 2011-07-19 17:10:50 UTC
Possible Dup of Bug 7891
Comment 3 Eric Solheim 2011-07-27 16:23:11 UTC
Bug still exists in RC3
Comment 4 Volker Lendecke 2011-07-27 19:24:34 UTC
Your log files are from winbind. We need the smbd log files.
Comment 5 Eric Solheim 2011-07-28 13:42:03 UTC
Created attachment 6725 [details]
SMB Logs for Bug

Here are two errors in the logs that are likely related.

[2011/07/28 09:19:03.948894,  5] smbd/smb2_signing.c:73(smb2_signing_sign_pdu)
  signed SMB2 message
  smbd_smb2_request_reply: sending...
  	req->in.vector[0].iov_len = 4
  	req->in.vector[1].iov_len = 64
  	req->in.vector[2].iov_len = 40
  	req->in.vector[3].iov_len = 0
  	req->out.vector[0].iov_len = 4
  	req->out.vector[1].iov_len = 64
  	req->out.vector[2].iov_len = 8
  	req->out.vector[3].iov_len = 4
[2011/07/28 09:19:03.949992, 10] smbd/smb2_server.c:2361(smbd_smb2_request_incoming)
  smbd_smb2_request_incoming: idx[1] of 4 vectors
[2011/07/28 09:19:03.950049, 10] smbd/smb2_server.c:345(smb2_validate_message_id)
  smb2_validate_message_id: clearing id 461 (position 205) from bitmap
[2011/07/28 09:19:03.950099, 10] smbd/smb2_server.c:1095(smbd_smb2_request_dispatch)
  smbd_smb2_request_dispatch: opcode[SMB2_IOCTL] mid = 461
[2011/07/28 09:19:03.950163,  4] smbd/uid.c:351(change_to_user)
  Skipping user change - already user
[2011/07/28 09:19:03.950213, 10] smbd/smb2_ioctl.c:249(smbd_smb2_ioctl_send)
  smbd_smb2_ioctl: file_id[0x0000000000003E19]
[2011/07/28 09:19:03.950277, 10] smbd/smb2_ioctl.c:138(smbd_smb2_request_ioctl_done)
  smbd_smb2_request_ioctl_done: smbd_smb2_ioctl_recv returned 0 status NT_STATUS_INVALID_DEVICE_REQUEST
[2011/07/28 09:19:03.950329, 10] smbd/smb2_server.c:1799(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_INVALID_DEVICE_REQUEST] || at smbd/smb2_ioctl.c:144
[2011/07/28 09:19:03.950379, 10] smbd/smb2_server.c:1702(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_INVALID_DEVICE_REQUEST] body[8] dyn[yes:1] at smbd/smb2_server.c:1830
[2011/07/28 09:19:03.950429, 10] smbd/smb2_server.c:472(smb2_set_operation_credit)
  smb2_set_operation_credit: requested 1, granted 1, total granted 31



[2011/07/28 09:19:05.762155,  5] smbd/smb2_signing.c:73(smb2_signing_sign_pdu)
  signed SMB2 message
  smbd_smb2_request_reply: sending...
  	req->in.vector[0].iov_len = 4
  	req->in.vector[1].iov_len = 64
  	req->in.vector[2].iov_len = 24
  	req->in.vector[3].iov_len = 0
  	req->out.vector[0].iov_len = 4
  	req->out.vector[1].iov_len = 64
  	req->out.vector[2].iov_len = 60
  	req->out.vector[3].iov_len = 0
[2011/07/28 09:19:05.763560, 10] smbd/smb2_server.c:2361(smbd_smb2_request_incoming)
  smbd_smb2_request_incoming: idx[1] of 4 vectors
[2011/07/28 09:19:05.763615, 10] smbd/smb2_server.c:345(smb2_validate_message_id)
  smb2_validate_message_id: clearing id 517 (position 5) from bitmap
[2011/07/28 09:19:05.763666, 10] smbd/smb2_server.c:1095(smbd_smb2_request_dispatch)
  smbd_smb2_request_dispatch: opcode[SMB2_CREATE] mid = 517
[2011/07/28 09:19:05.763738,  4] smbd/uid.c:351(change_to_user)
  Skipping user change - already user
[2011/07/28 09:19:05.763796, 10] smbd/smb2_create.c:455(smbd_smb2_create_send)
  smbd_smb2_create: name[SambaTestCase\testcase.zip:Zone.Identifier]
[2011/07/28 09:19:05.763851,  5] smbd/filename.c:257(unix_convert)
  unix_convert called on file "SambaTestCase/testcase.zip:Zone.Identifier"
[2011/07/28 09:19:05.763904, 10] smbd/statcache.c:280(stat_cache_lookup)
  stat_cache_lookup: lookup succeeded for name [SAMBATESTCASE/TESTCASE.ZIP] -> [SambaTestCase/testcase.zip]
[2011/07/28 09:19:05.763975, 10] smbd/filename.c:1203(build_stream_path)
  comparing [:Zone.Identifier] and [::$DATA]: not equal
[2011/07/28 09:19:05.764028,  3] smbd/vfs.c:905(check_reduced_name)
  check_reduced_name [SambaTestCase/testcase.zip] [/data/erb]
[2011/07/28 09:19:05.764102, 10] smbd/vfs.c:969(check_reduced_name)
  check_reduced_name realpath [SambaTestCase/testcase.zip] -> [/data/erb/SambaTestCase/testcase.zip]
[2011/07/28 09:19:05.764151,  3] smbd/vfs.c:1039(check_reduced_name)
  check_reduced_name: SambaTestCase/testcase.zip reduced to /data/erb/SambaTestCase/testcase.zip
[2011/07/28 09:19:05.764201, 10] smbd/open.c:3760(create_file_default)
  create_file: access_mask = 0x80 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x200000 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = SambaTestCase/testcase.zip:Zone.Identifier
[2011/07/28 09:19:05.764261, 10] smbd/open.c:3864(create_file_default)
  create_file: NT_STATUS_OBJECT_NAME_NOT_FOUND
[2011/07/28 09:19:05.764322,  4] smbd/sec_ctx.c:314(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2011/07/28 09:19:05.764370,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2011/07/28 09:19:05.764417,  5] auth/token_util.c:527(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2011/07/28 09:19:05.764512,  5] smbd/uid.c:400(change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2011/07/28 09:19:05.764574, 10] smbd/smb2_server.c:1799(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at smbd/smb2_create.c:308
[2011/07/28 09:19:05.764626, 10] smbd/smb2_server.c:1702(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] body[8] dyn[yes:1] at smbd/smb2_server.c:1830
[2011/07/28 09:19:05.764679, 10] smbd/smb2_server.c:472(smb2_set_operation_credit)
Comment 6 Eric Solheim 2011-07-29 15:09:37 UTC
Created attachment 6730 [details]
Install Instructions and smb.conf file

Volker, 
I have added the smb.conf file and install instructions to be more complete can you tell from the logs if I should reclassify the component as SMB2?
Also let me know if there is anything I can provide that would help track this down.
Thanks,
Eric
Comment 7 Stefan Metzmacher 2012-05-10 13:35:21 UTC
Maybe the problem is that smb2_ioctl.c doesn't handle the same
fsctl opcodes as nttrans.c.
Comment 8 Eric Solheim 2012-05-10 14:43:41 UTC
Still exists in 3.6.4 were you able to replicate the bug?
Comment 9 Stefan Metzmacher 2012-05-29 11:55:59 UTC
Created attachment 7602 [details]
Untested patch for 3.6

Can you apply and test this patches?
Comment 10 Stefan Metzmacher 2012-05-31 11:35:01 UTC
Comment on attachment 7602 [details]
Untested patch for 3.6

Jeremy, David, Richard, would this be fine for 3.6?

Can someone test this?
Comment 11 Eric Solheim 2012-05-31 12:34:31 UTC
(In reply to comment #9)
> Created attachment 7602 [details]
> Untested patch for 3.6
> 
> Can you apply and test this patches?

Sorry will post later today.
Comment 12 Jeremy Allison 2012-05-31 22:03:40 UTC
Will try and get to this tomorrow.

Jeremy.
Comment 13 Jeremy Allison 2012-06-01 22:10:04 UTC
I like the patch, I just *hate* the SMB_VFS_FSCTL() name. As it isn't really a vfs function we should just call it smb_fsctl() (IMHO) so we don't confuse people into thinking this is vectored.

Jeremy.
Comment 14 Eric Solheim 2012-06-04 14:42:07 UTC
(In reply to comment #11)
> (In reply to comment #9)
> > Created attachment 7602 [details] [details]
> > Untested patch for 3.6
> > 
> > Can you apply and test this patches?
> 
> Sorry will post later today.

Sorry for the delay code works fine, so far 
no evidence of bug.
Comment 15 Jeremy Allison 2012-06-04 23:01:38 UTC
Comment on attachment 7602 [details]
Untested patch for 3.6

I hate the SMB_VFS_FSCTL() function name as it's really confusing for VFS users. I have a version of this patch that calls this function smb_fsctl() instead which I'll upload.

Jeremy.
Comment 16 Jeremy Allison 2012-06-04 23:03:06 UTC
Created attachment 7625 [details]
git-am fix for 3.6.next.

Here's the modified version. It's the same code that the reporter just reported as working, with the change of SMB_VFS_FSCTL() -> smb_fsctl()

Jeremy.
Comment 17 Stefan Metzmacher 2012-06-05 06:08:19 UTC
Comment on attachment 7625 [details]
git-am fix for 3.6.next.

Looks ok
Comment 18 Stefan Metzmacher 2012-06-05 06:08:46 UTC
Karolin, please pick for the release
Comment 19 Karolin Seeger 2012-06-13 17:45:41 UTC
Pushed to v3-6-test.
Closing out bug report.

Thanks!