Bug 7940 - Error opening Powerpoint files
Summary: Error opening Powerpoint files
Status: RESOLVED FIXED
Alias: None
Product: Samba 3.5
Classification: Unclassified
Component: File services (show other bugs)
Version: 3.5.6
Hardware: x86 Linux
: P3 regression
Target Milestone: ---
Assignee: Jeremy Allison
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-01-28 11:09 UTC by Tom Aeby
Modified: 2011-02-09 14:03 UTC (History)
2 users (show)

See Also:


Attachments
tcpdump capture file ready for analyse with wireshark (203.58 KB, application/octet-stream)
2011-01-28 12:37 UTC, Tom Aeby
no flags Details
Patch (1.66 KB, patch)
2011-01-29 04:09 UTC, Volker Lendecke
jra: review+
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Tom Aeby 2011-01-28 11:09:32 UTC
On Samba servers running Samba 3.5.6 (also tested with 3.4.9) we get an error "There was an error accessing ...ppt" when trying to open certain Powerpoint files with MS Powerpoint 2010

  - Tested with Office 2010 on a Windows 7 client
  - happens with 3.4.9 and 3.5.6
  - does not happen with 3.3.14 and 3.0.28 
  - not tested with other office, windows and samba versions
  - does only happen with some ppt files (unclear, those that
    cannot be opened from a share are immediately rewritten during
    opening them from a non-Samba location)
  - Samba (sernet-samba packages) on Debian/lenny (others untested)
  - tried out multiple configurations, happens with a most basic
    configuration (appended below) as well as with a sophisticated one

Running smbd with debug level 10 I have seen one interesting error in the log (see below) that does not appear when running 3.3.14. However, I am unsure if this is significant. The entire error log is available from http://tuallix.graeff.com/ppt_samba_err.txt.

Please let me know if I can do more testing for you, we have set up a test environment we can reproduce the error in. I can provide a .ppt triggering the problem on request.

Best regards,
Tom
========================= excerpt from smbd log ======================
[...]
 smb_vwv[14]=    8 (0x8)
  smb_bcc=51
[2011/01/28 16:48:28.600363, 10] ../lib/util/util.c:278(_dump_data)
  [0000] 00 00 00 18 48 EC 03 00   00 00 00 00 00 00 00 00   ....H... ........
  [0010] 00 00 00 00 00 00 00 00   00 00 00 60 9A 7F CE 02   ........ ...`....
  [0020] BF CB 01 00 00 00 00 00   00 00 00 00 00 00 00 00   ........ ........
  [0030] 00 00 00                                          ...
[2011/01/28 16:48:28.600421,  3] smbd/process.c:1294(switch_message)
  switch message SMBtrans2 (pid 5148) conn 0x809d52c0
[2011/01/28 16:48:28.600434,  4] smbd/uid.c:257(change_to_user)
  change_to_user: Skipping user change - already user
[2011/01/28 16:48:28.600449,  3] smbd/trans2.c:7722(call_trans2setfilepathinfo)
  call_trans2setfilepathinfo(8) IBA/test2.ppt (fnum 18456) info_level=1004 totdata=40
[2011/01/28 16:48:28.600463,  3] smbd/trans2.c:7320(smbd_do_setfilepathinfo)
  smbd_do_setfilepathinfo: IBA/test2.ppt (fnum 18456) info_level=1004 totdata=40
[2011/01/28 16:48:28.600477,  6] smbd/trans2.c:5518(smb_set_file_dosmode)
  smb_set_file_dosmode: dosmode: 0x0
[2011/01/28 16:48:28.600490, 10] smbd/trans2.c:6303(smb_set_file_basic_info)
  smb_set_file_basic_info: file IBA/test2.ppt
[2011/01/28 16:48:28.600502,  5] smbd/trans2.c:5436(smb_set_file_time)
  smb_set_filetime: actime: Thu Jan  1 01:00:00 1970

   smb_set_filetime: modtime: Fri Jan 28 16:48:29 2011

   smb_set_filetime: ctime: Thu Jan  1 01:00:00 1970

   smb_set_file_time: createtime: Thu Jan  1 01:00:00 1970

   smb_set_file_time: setting pending modtime to Fri Jan 28 16:48:29 2011

[2011/01/28 16:48:28.600557,  5] locking/locking.c:1475(set_sticky_write_time)
  set_sticky_write_time: Fri 28 Jan 2011 04:48:29 PM CET CET id=303:1e45fe:0
[2011/01/28 16:48:28.600588, 10] lib/dbwrap_tdb.c:100(db_tdb_fetch_locked)
  Locking key 0303000000000000FE45
[2011/01/28 16:48:28.600605, 10] lib/dbwrap_tdb.c:129(db_tdb_fetch_locked)
  Allocated locked data 0x0x809b3d08
[2011/01/28 16:48:28.600617, 10] locking/locking.c:552(parse_share_modes)
  parse_share_modes: delete_on_close: 0, owrt: Fri 28 Jan 2011 04:24:08 PM CET CET, cwrt: Thu 01 Jan 1970 01:00:00 AM CET CET, tok: 0, num_share_modes: 2
[2011/01/28 16:48:28.600650, 10] locking/locking.c:655(parse_share_modes)
  parse_share_modes: share_mode_entry[0]:  pid = 5148, share_access = 0x1, private_options = 0x40, access_mask = 0x2019f, mid = 0x0, type= 0x0, gen_id = 140, uid = 1006, flags = 0, file_id 303:1e45fe:0
[2011/01/28 16:48:28.600671, 10] locking/locking.c:655(parse_share_modes)
  parse_share_modes: share_mode_entry[1]: UNUSED pid = 5148, share_access = 0x3, private_options = 0x40, access_mask = 0x20089, mid = 0x0, type= 0x40, gen_id = 146, uid = 1006, flags = 0, file_id 303:1e45fe:0
[2011/01/28 16:48:28.600685, 10] locking/locking.c:726(unparse_share_modes)
  unparse_share_modes: del: 0, owrt: Fri 28 Jan 2011 04:24:08 PM CET CET cwrt: Fri 28 Jan 2011 04:48:29 PM CET CET, tok: 0, num: 2
[2011/01/28 16:48:28.600716, 10] locking/locking.c:518(print_share_mode_table)
  print_share_mode_table: share_mode_entry[0]:  pid = 5148, share_access = 0x1, private_options = 0x40, access_mask = 0x2019f, mid = 0x0, type= 0x0, gen_id = 140, uid = 1006, flags = 0, file_id 303:1e45fe:0
[2011/01/28 16:48:28.600736, 10] locking/locking.c:518(print_share_mode_table)
  print_share_mode_table: share_mode_entry[1]: UNUSED pid = 5148, share_access = 0x3, private_options = 0x40, access_mask = 0x20089, mid = 0x0, type= 0x40, gen_id = 146, uid = 1006, flags = 0, file_id 303:1e45fe:0
[2011/01/28 16:48:28.600752, 10] lib/dbwrap_tdb.c:42(db_tdb_record_destr)
  Unlocking key 0303000000000000FE45
[2011/01/28 16:48:28.600771, 10] smbd/trans2.c:5472(smb_set_file_time)
  smb_set_file_time: setting utimes to modified values.
[2011/01/28 16:48:28.600783,  6] smbd/dosmode.c:861(file_ntimes)
  file_ntime: actime: Thu Jan  1 01:00:00 1970
[2011/01/28 16:48:28.600799,  6] smbd/dosmode.c:863(file_ntimes)
  file_ntime: modtime: Fri Jan 28 16:48:29 2011
[2011/01/28 16:48:28.600814,  6] smbd/dosmode.c:865(file_ntimes)
  file_ntime: ctime: Thu Jan  1 01:00:00 1970
[2011/01/28 16:48:28.600830,  6] smbd/dosmode.c:867(file_ntimes)
  file_ntime: createtime: Thu Jan  1 01:00:00 1970
[2011/01/28 16:48:28.600847,  3] smbd/error.c:80(error_packet_set)
  error packet at smbd/trans2.c(7759) cmd=50 (SMBtrans2) NT_STATUS_NOT_SUPPORTED
[2011/01/28 16:48:28.600861,  5] lib/util.c:617(show_msg)
[2011/01/28 16:48:28.600869,  5] lib/util.c:627(show_msg)
  size=35
[...]
====================== smb.conf ========================================
[global]
	workgroup = MYGROUP
	server string = Samba Server
	passdb backend = smbpasswd
	log file = /usr/local/samba/var/log.%m
	max log size = 50
	dns proxy = No

[homes]
	comment = Home Directories
	read only = No
	browseable = No
Comment 1 Jeremy Allison 2011-01-28 11:53:56 UTC
Can you upload a wireshark capture trace of this occurring please ? I'd like to see what is returning the NT_STATUS_NOT_SUPPORTED.

Thanks !

Jeremy.
Comment 2 Tom Aeby 2011-01-28 12:37:44 UTC
Created attachment 6233 [details]
tcpdump capture file ready for analyse with wireshark

captured with tcpdump -s 1600 -w ... ready for wireshark -r
Comment 3 Volker Lendecke 2011-01-29 03:53:59 UTC
Is it possible that you are using an older kernel than debian lenny? What file system are you sharing?

Volker
Comment 4 Volker Lendecke 2011-01-29 04:09:36 UTC
Created attachment 6234 [details]
Patch

The attached patch applies to both master and 3.6.

It seems that we try a utimes version that the kernel this system is running does not support. We do not do a proper fallback, which this patch implements.

I'm not pushing it right away because I could swear that we have talked about exactly this topic a couple of months ago. I can't find any reference to it, so I'm not sure this or a similar solution was turned down deliberately.

Volker
Comment 5 Volker Lendecke 2011-01-29 04:11:14 UTC
Björn, do you remember that discussion and the outcome? It might have been internal.

Volker
Comment 6 Tom Aeby 2011-01-29 04:33:34 UTC
Volker,

you are right, we are running 2.6.18 on this systems due to some dependencies, sorry for not having mentioned that before. The underlying file system is XFS.

Best regards,
Tom
Comment 7 Volker Lendecke 2011-01-29 05:25:59 UTC
Ok, the older kernel is the problem here. I'm very certain that the attached patch (or a similar one) will fix the problem.

We'll discuss soon how to proceed here.

Volker
Comment 8 Björn Jacke 2011-01-31 03:21:34 UTC
the outcome was that this kernel/libc combination is unsupported/invalid and we want to refuse to start in case utimensat returns ENOSYS. Not yet done ...
Comment 9 Volker Lendecke 2011-01-31 03:28:43 UTC
Ok. I would still argue that we could do the workaround patch I proposed, but if the Samba Team decides that we should stop supporting configurations that we *could* support, I can provide a different patch.
Comment 10 Volker Lendecke 2011-01-31 03:29:49 UTC
Jeremy, do you have an opinion here?
Comment 12 Tom Aeby 2011-01-31 03:58:33 UTC
Maybe this is redundant information: I confirm the problem is gone after upgrading to kernel 2.6.26.

If I may put my opinion in from the admins point of view: It is acceptable that Samba does not try to work around the problem (would be nice, anyway, especially since older Samba versions did work in this configuration), but should then at least log a meaningful error message.

Best regards,
Tom
Comment 13 Björn Jacke 2011-01-31 04:03:47 UTC
yes, that is definetely the recommended thing to do.
Comment 14 Jeremy Allison 2011-01-31 18:03:48 UTC
Comment on attachment 6234 [details]
Patch

+1 on the patch from me. Anything that makes us fallback better works for me. Is there a reason we shouldn't fall back here ?
Jeremy.
Comment 15 Jeremy Allison 2011-01-31 18:07:24 UTC
Oh wait a minute - just read the linked-to thread.

"Therefore I'd prefer the
> > attached short patch without any fallback code.
> +1 from me. Last thing we need are more obscure failure modes :-). "


Maybe we should just call smb_panic() on result == -1 && errno == ENOSYS with an appropriate error message.

Jeremy.
Comment 16 Volker Lendecke 2011-02-01 00:52:40 UTC
(In reply to comment #15)
> Oh wait a minute - just read the linked-to thread.
> 
> "Therefore I'd prefer the
> > > attached short patch without any fallback code.
> > +1 from me. Last thing we need are more obscure failure modes :-). "
> 
> 
> Maybe we should just call smb_panic() on result == -1 && errno == ENOSYS with
> an appropriate error message.

No, this would be wrong. We would need to add this test to the smbd startup routine. I still vote for the fallback, my 10ct...

Volker
Comment 17 Jeremy Allison 2011-02-01 10:32:50 UTC
Ok, after talking with Volker I'm happy with the patch. Re-assigning to Karolin for inclusion in 3.5.next.

Jeremy.
Comment 18 Karolin Seeger 2011-02-05 11:47:44 UTC
Pushed to v3-5-test.
Will be included in the next bugfix release.
Closing out bug report.

Thanks!
Comment 19 Björn Jacke 2011-02-08 12:43:40 UTC
this still looks wrong to me as we already discussed in the thread mentioned in comment 11.

The very least me miss now is the fix that Janek posted there for the vfswrap_fs_capabilities function because it returns the wrong result on broken/unsupported glibc/kernel combinations.

But Jeremy: in that mentioned thread you agreed that trying to support a broken setup and possibly waiting for other jet unknown other obcure erors is a bad idea - why do you want to do that now?
Comment 20 Karolin Seeger 2011-02-09 13:53:32 UTC
Re-assigning to Jeremy to comment.

This is a blocker for 3.5.7 now, because I am not sure whether I shall revert the patch or not. 
Comment 21 Jeremy Allison 2011-02-09 13:57:04 UTC
Volkers fall back fix is the correct one. Don't revert - this is not a blocker.
Jeremy.
Comment 22 Björn Jacke 2011-02-09 14:03:27 UTC
and vfswrap_fs_capabilities() returning the wrong thing is okay?