Closed gregfreemyer closed 9 years ago
joachimmetz
commented
9 years ago Nothing in the backtrace seems related to log2timeline, so I I wonder if something stomped on memory it should not have? (Can that happen in python?)
Yes it can, often a compiled C python module misbehaving. Since you're running on OSX the reason can be multiple.
How did you install the dependencies? Installed prebuilt? compiled them yourself? What versions of the dependencies do you have installed?
gregfreemyer
commented
9 years ago Yes it can, often a compiled C python module misbehaving.
Good old c code. That I understand.
Since you're running on OSX the reason can be multiple.
No, I'm running on Linux, just the image is of a Mac.
How did you install the dependencies? Installed prebuilt? compiled them yourself?
Compiled myself into rpms, then installed the rpms.
What versions of the dependencies do you have installed?
check_dependencies is running clean except one info message that a newer version of pyesedb is available
==== the below may make more sense on the mailing list.
Since I'm compiling the libyal dependencies in a non-standard way, the problem can be there easily.
Is there a reference setup i could run? I could setup a dedicated VM that builds the Libyal packages via the mechanism provided with plaso. opensuse and fedora are the Linux distros I know best, but I'm sure I could manage any Linux well enough to get that going. Are any of the developers routinely developing under Linux?
Then for situations like this and the one where IPC seems to have halted I could verify the finding in that VM and make sure it is not caused by the way I'm building the libyal rpms.
joachimmetz
commented
9 years ago Since I'm compiling the libyal dependencies in a non-standard way, the problem can be there easily.
Or the other C/C++ based depencies for that matter. Try:
gdb --ex r --args python log2timeline.py --single-process ...See if you can generate a backtrace of a single process with line numbers. Based on your current backtrace I would say it's a bug in libtsk/pytsk3.
/lib64/libc.so.6(+0x730bf)[0x7fe8739dc0bf]
/lib64/libc.so.6(+0x7892e)[0x7fe8739e192e]
/usr/lib64/libtsk.so.10(hfs_file_read_special+0x615)[0x7fe86c7c7045]Also see: http://plaso.kiddaland.net/developer/troubleshooting
gregfreemyer
commented
9 years ago I don't know if it is the same backtrace, but I got this when I ran log2timeline.py with a few day old git head in gdb:
Source path : /mnt-ewf/ewf1 Is storage media image or device : True Partition offset : 209735680 (0x0c805000)
/usr/lib/python2.7/site-packages/plaso/parsers/plist_plugins/airport.py(56)GetEntries() -> u'/RememberedNetworks', u'item', wifi['LastConnected'], description)
In the log file I got the below at the tail of the log at the same time:
2014-12-02 20:04:51,660 DEBUG PID:25548
[plist] Wrong plugin: plist_spotlight_volume for: com.apple.airport.preferences.plist 2014-12-02 20:04:51,660 DEBUG PID:25548 [plist] Wrong plugin: plist_appleaccount for: com.apple.airport.preferences.plist 2014-12-02 20:04:51,660 DEBUG PID:25548 Plist Plugin Used: plist_airport for: com.apple.airport.preferences.plist 2014-12-02 20:04:51,661 WARNING PID:25548 [plist] Unable to process file: type: OS, location: /mnt-ewf/ewf1 type: RAW type: TSK_PARTITION, location: /p2, part index: 5, start offset: 0x0c805000 type: TSK, inode: 5179769, location: /.MobileBackups/Computer/2014-11-15-231022/Volume/Library/Preferences/SystemConfiguration/com.apple.airport.preferences.plist with error: 'LastConnected'. 2014-12-02 20:04:51,661 DEBUG PID:25548 The path specification that caused the error: type: OS, location: /mnt-ewf/ewf1 type: RAW type: TSK_PARTITION, location: /p2, part index: 5, start offset: 0x0c805000 type: TSK, inode: 5179769, location: /.MobileBackups/Computer/2014-11-15-231022/Volume/Library/Preferences/SystemConfiguration/com.apple.airport.preferences.plist 2014-12-02 20:04:51,661 ERROR PID:25548
'LastConnected' Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/plaso/engine/worker.py", line 123, in _ParseFileEntryWithParser parser_object.Parse(self._parser_context, file_entry) File "/usr/lib/python2.7/site-packages/plaso/parsers/plist.py", line 150, in Parse plist_name=plist_name, top_level=top_level_object) File "/usr/lib/python2.7/site-packages/plaso/parsers/plist_plugins/interface.py", line 192, in Process top_level=top_level, match=match) File "/usr/lib/python2.7/site-packages/plaso/parsers/plist_plugins/airport.py", line 56, in GetEntries u'/RememberedNetworks', u'item', wifi['LastConnected'], description) KeyError: 'LastConnected'
After that I did "cont" so I'll post the next traceback in the the next comment. I have a feeling there are several different ones. Let me know if I need to create new issues for each traceback.
gregfreemyer
commented
9 years ago 2nd traceback from running gdb:
On GDB output console:
(Pdb) cont /usr/lib/python2.7/site-packages/construct/core.py(305)_read_stream() -> raise FieldError("expected %d, found %d" % (length, len(data)))
From tail of logfile:
2014-12-02 20:14:17,562 DEBUG PID:25548
Not a bsm_log file (login.keychain) - Not a BSM File, unable to parse. 2014-12-02 20:14:17,562 DEBUG PID:25548 Trying to parse: login.keychain with parser: mac_keychain 2014-12-02 20:14:17,566 WARNING PID:25548 [mac_keychain] Unable to process file: type: OS, location: /mnt-ewf/ewf1 type: RAW type: TSK_PARTITION, location: /p2, part index: 5, start offset: 0x0c805000 type: TSK, inode: 5180593, location: /.MobileBackups/Computer/2014-11-15-231022/Volume/Users/M /Library/Keychains/login.keychain with error: expected 83886081, found 43865. 2014-12-02 20:14:17,566 DEBUG PID:25548 The path specification that caused the error: type: OS, location: /mnt-ewf/ewf1 type: RAW type: TSK_PARTITION, location: /p2, part index: 5, start offset: 0x0c805000 ty /Library/Keychains/login.keychain 2014-12-02 20:14:17,566 ERROR PID:25548
expected 83886081, found 43865 Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/plaso/engine/worker.py", line 123, in _ParseFileEntryWithParser parser_object.Parse(self._parser_context, file_entry) File "/usr/lib/python2.7/site-packages/plaso/parsers/mac_keychain.py", line 490, in Parse parser_chain=parser_chain) File "/usr/lib/python2.7/site-packages/plaso/parsers/mac_keychain.py", line 254, in _ReadEntryApplication parser_context, file_entry, file_object, record.record_header, offset) File "/usr/lib/python2.7/site-packages/plaso/parsers/mac_keychain.py", line 322, in _ReadEntryHeader comments = self.TEXT.parse_stream(file_object) File "/usr/lib/python2.7/site-packages/construct/core.py", line 198, in parse_stream return self._parse(stream, Container()) File "/usr/lib/python2.7/site-packages/construct/core.py", line 288, in _parse return self._decode(self.subcon._parse(stream, context), context) File "/usr/lib/python2.7/site-packages/construct/core.py", line 288, in _parse return self._decode(self.subcon._parse(stream, context), context) File "/usr/lib/python2.7/site-packages/construct/core.py", line 733, in _parse subobj = sc._parse(stream, context) File "/usr/lib/python2.7/site-packages/construct/core.py", line 398, in _parse return _read_stream(stream, self.lengthfunc(context)) File "/usr/lib/python2.7/site-packages/construct/core.py", line 305, in _read_stream raise FieldError("expected %d, found %d" % (length, len(data))) FieldError: expected 83886081, found 43865
joachimmetz
commented
9 years ago Let's stick with the C stack trace in this issue and don't add noise to the issue. It makes the issue hard to follow for people.
Regarding the python tracebacks of certain parsers these are should not halt the tool. It is WIP to handle this without spamming the console output.
gregfreemyer
commented
9 years ago Okay,
I got 4 of the python backtraces total. Each time gdb stopped, but I just told it to continue. After that (and time) I got the C stack trace. It looks basically the same to me, so even though I installed lots of *.debuginfo packages it doesn't seem to have helped.
At the end of stack track / memory map, gdb did output:
Program received signal SIGABRT, Aborted. 0x00007ffff749c187 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory. Missing separate debuginfos, use: zypper install libncurses5-debuginfo-5.9-52.2.3.x86_64 libreadline6-debuginfo-6.2-75.4.1.x86_64
I'll install those last 2 debuginfo packages, but I don't see that changing the stacktrace much.
Here's the stack trace that came out this time
(Pdb) cont * Error in `/usr/bin/python': free(): invalid pointer: 0x0000000025c4b120 * ======= Backtrace: ========= /lib64/libc.so.6(+0x730bf)[0x7ffff74da0bf] /lib64/libc.so.6(+0x7892e)[0x7ffff74df92e] /usr/lib64/libtsk.so.10(hfs_file_read_special+0x615)[0x7ffff02c5045] /usr/lib64/python2.7/site-packages/pytsk3.so(+0x1a2b9)[0x7ffff05a62b9] /usr/lib64/python2.7/site-packages/pytsk3.so(+0xb4ec)[0x7ffff05974ec] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x1295)[0x7ffff7af43e5] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x221)[0x7ffff7afa061] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x221)[0x7ffff7afa061] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x221)[0x7ffff7afa061] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x4fe)[0x7ffff7afa33e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x4fe)[0x7ffff7afa33e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x4fe)[0x7ffff7afa33e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x4fe)[0x7ffff7afa33e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x4fe)[0x7ffff7afa33e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0xc74)[0x7ffff7af3dc4] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2a0e)[0x7ffff7af5b5e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x4fe)[0x7ffff7afa33e] /usr/lib64/libpython2.7.so.1.0(PyEval_EvalCode+0x32)[0x7ffff7b27142] /usr/lib64/libpython2.7.so.1.0(+0x1078ad)[0x7ffff7b338ad] /usr/lib64/libpython2.7.so.1.0(PyRun_FileExFlags+0x92)[0x7ffff7ac16ad] /usr/lib64/libpython2.7.so.1.0(PyRun_SimpleFileExFlags+0x308)[0x7ffff7ac2294] /usr/lib64/libpython2.7.so.1.0(Py_Main+0xc60)[0x7ffff7ac9e63] /lib64/libc.so.6(__libc_start_main+0xf5)[0x7ffff7488b05] /usr/bin/python[0x40078e]
gregfreemyer
commented
9 years ago I forgot to say, I still have gdb open at the command prompt if there is anything useful to query. It is a few years since I used gdb, so exact syntax would be appreciated.
joachimmetz
commented
9 years ago It looks basically the same to me, so even though I installed lots of *.debuginfo packages it doesn't seem to have helped.
You don't need all the debug symbol packages just those for the plaso dependencies, which I recall you built yourself. On Fedora these are auto generated by rpmbuild; not sure about your configuration.
Here's the stack trace that came out this time
Alas that does not help me much, as indicated I need the line number where the crash occurs to start looking without the actual data. I also don't see the frame numbers in your output. E.g.
#0 0x0000003457247e98 in _IO_vfprintf_internal (s=<optimized out>, format=<optimized out>, ap=ap@entry=0x7fffffffdf08) at vfprintf.c:1615
#1 0x0000003457250ed9 in __printf (format=<optimized out>) at printf.c:34
#2 0x00000000004005e5 in main () at crash.c:10However it seems the crash point is consistent, which hopefully means it is not a hard to troubleshoot bug once the line number is known.
An alternative approach would be to build libtsk and pytsk with debug symbols. See: http://code.google.com/p/pytsk/wiki/Troubleshooting. And replace the currently shared object with the debug symbol versions.
I forgot to say, I still have gdb open at the command prompt if there is anything useful to query.
That could be useful, thanks. Try:
frame 2
listIn theory I have debug symbols installed. I'll ask elsewhere to make sure I've done it right:
rpm -qa | grep tsk
python-tsk-debuginfo-0~20140506-5.1.x86_64
python-tsk-0~20140506-5.1.x86_64
libtsk10-debuginfo-4.1.3-4.1.x86_64
libtsk10-4.1.3-4.1.x86_64Here's the gdb output:
(gdb) frame 2
#2 0x00007ffff74da0c4 in __libc_message (do_abort=do_abort@entry=2,
fmt=fmt@entry=0x7ffff75cc310 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/posix/libc_fatal.c:175
175 ../sysdeps/posix/libc_fatal.c: No such file or directory.
(gdb) list
170 in ../sysdeps/posix/libc_fatal.c
(gdb) I will leave it in gdb for now.
joachimmetz
commented
9 years ago Since I see the line numbers here. So I'm wondering where you got the other backtrace from. Can you run in gdb:
btThe previous back trace was just dumped on my konsole screen. I did not actually request it from gdb. bt works much better.
Remember I am running: python-tsk-0~20140506-5.1.x86_64 libtsk10-4.1.3-4.1.x86_64
> (gdb) bt
#0 0x00007ffff749c187 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x00007ffff749d538 in __GI_abort () at abort.c:78
#2 0x00007ffff74da0c4 in __libc_message (do_abort=do_abort@entry=2,
fmt=fmt@entry=0x7ffff75cc310 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/posix/libc_fatal.c:175
#3 0x00007ffff74df92e in malloc_printerr (action=3, str=0x7ffff75c84ef "free(): invalid pointer", ptr=<optimized out>)
at malloc.c:4991
#4 0x00007ffff02c5045 in hfs_file_read_special (a_fs_attr=<optimized out>, a_offset=<optimized out>,
a_buf=0x7fffdd38d034 "%PDF-1.4\r%\342\343\317\323\r\n480 0 obj\r<</Linearized 1/L 8455993/O 483/E 5268558/N 10/T 8446277/H [ 9756 1018]>>\rendobj\r \rxref\r480 473\r0000000016 00000 n\r\n0000010946 00000 n\r\n0000011190 00000 n\r\n0000011252 "...,
a_len=<optimized out>) at hfs.c:3257
#5 0x00007ffff05a62b9 in File_read_random (self=<optimized out>, offset=<optimized out>, buff=<optimized out>, len=<optimized out>,
type=<optimized out>, id=<optimized out>, flags=TSK_FS_FILE_READ_FLAG_NONE) at tsk3.c:490
#6 0x00007ffff05974ec in pyFile_read_random (self=0x7fffdd4e97f0, args=<optimized out>, kwds=<optimized out>) at pytsk3.c:14333
#7 0x00007ffff7af43e5 in call_function (oparg=<optimized out>, pp_stack=0x7fffffffa560) at Python/ceval.c:4033
#8 PyEval_EvalFrameEx (f=f@entry=0x7fffe311a050, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#9 0x00007ffff7afa061 in PyEval_EvalCodeEx (co=0x7ffff09f83b0, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=2, kws=<optimized out>, kwcount=0, defs=0x7ffff09ee9e8, defcount=1, closure=0x0)
at Python/ceval.c:3265
#10 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=2, n=<optimized out>, pp_stack=0x7fffffffa790, func=<optimized out>)
at Python/ceval.c:4129
#11 call_function (oparg=<optimized out>, pp_stack=0x7fffffffa790) at Python/ceval.c:4054
#12 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a1ba00, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#13 0x00007ffff7afa061 in PyEval_EvalCodeEx (co=0x7fffed328230, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=2, kws=<optimized out>, kwcount=0, defs=0x7fffed339268, defcount=1, closure=0x0)
at Python/ceval.c:3265
#14 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=2, n=<optimized out>, pp_stack=0x7fffffffa9c0, func=<optimized out>)
at Python/ceval.c:4129
#15 call_function (oparg=<optimized out>, pp_stack=0x7fffffffa9c0) at Python/ceval.c:4054
#16 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a20a50, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#17 0x00007ffff7afa061 in PyEval_EvalCodeEx (co=0x7fffed3287b0, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=2, kws=<optimized out>, kwcount=0, defs=0x7fffed3392a8, defcount=1, closure=0x0)
at Python/ceval.c:3265
#18 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=2, n=<optimized out>, pp_stack=0x7fffffffabf0, func=<optimized out>)
at Python/ceval.c:4129
#19 call_function (oparg=<optimized out>, pp_stack=0x7fffffffabf0) at Python/ceval.c:4054
#20 PyEval_EvalFrameEx (f=f@entry=0x1b98c9a0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#21 0x00007ffff7afa33e in PyEval_EvalCodeEx (co=0x7fffebd7bbb0, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=4, kws=<optimized out>, kwcount=2, defs=0x7fffebd75ce8, defcount=3, closure=0x0)
at Python/ceval.c:3265
#22 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=4, n=<optimized out>, pp_stack=0x7fffffffae20, func=<optimized out>)
at Python/ceval.c:4129
#23 call_function (oparg=<optimized out>, pp_stack=0x7fffffffae20) at Python/ceval.c:4054
#24 PyEval_EvalFrameEx (f=f@entry=0x167930d0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#25 0x00007ffff7afa33e in PyEval_EvalCodeEx (co=0x7fffebd7bd30, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=3, kws=<optimized out>, kwcount=0, defs=0x7fffebd8e828, defcount=1, closure=0x0)
at Python/ceval.c:3265
#26 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=3, n=<optimized out>, pp_stack=0x7fffffffb050, func=<optimized out>)
at Python/ceval.c:4129
#27 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb050) at Python/ceval.c:4054
#28 PyEval_EvalFrameEx (f=f@entry=0x7fffe3052da8, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#29 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffb1d0,
func=<optimized out>) at Python/ceval.c:4119
#30 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb1d0) at Python/ceval.c:4054
#31 PyEval_EvalFrameEx (f=f@entry=0x7fffe3050620, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#32 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffb350,
func=<optimized out>) at Python/ceval.c:4119
#33 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb350) at Python/ceval.c:4054
#34 PyEval_EvalFrameEx (f=f@entry=0x7fffe311c050, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#35 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffb4d0,
func=<optimized out>) at Python/ceval.c:4119
#36 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb4d0) at Python/ceval.c:4054
#37 PyEval_EvalFrameEx (f=f@entry=0x2bce760, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#38 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffb650,
func=<optimized out>) at Python/ceval.c:4119
#39 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb650) at Python/ceval.c:4054
#40 PyEval_EvalFrameEx (f=f@entry=0x2bd9db0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#41 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffb7d0,
func=<optimized out>) at Python/ceval.c:4119
#42 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb7d0) at Python/ceval.c:4054
#43 PyEval_EvalFrameEx (f=f@entry=0x150b8910, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#44 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffb950,
func=<optimized out>) at Python/ceval.c:4119
#45 call_function (oparg=<optimized out>, pp_stack=0x7fffffffb950) at Python/ceval.c:4054
#46 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a1dd38, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#47 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffbad0,
func=<optimized out>) at Python/ceval.c:4119
#48 call_function (oparg=<optimized out>, pp_stack=0x7fffffffbad0) at Python/ceval.c:4054
#49 PyEval_EvalFrameEx (f=f@entry=0x1223f130, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#50 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffbc50,
func=<optimized out>) at Python/ceval.c:4119
#51 call_function (oparg=<optimized out>, pp_stack=0x7fffffffbc50) at Python/ceval.c:4054
#52 PyEval_EvalFrameEx (f=f@entry=0xbdaf8d0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#53 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffbdd0,
func=<optimized out>) at Python/ceval.c:4119
#54 call_function (oparg=<optimized out>, pp_stack=0x7fffffffbdd0) at Python/ceval.c:4054
#55 PyEval_EvalFrameEx (f=f@entry=0x1222e7f0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#56 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffbf50,
func=<optimized out>) at Python/ceval.c:4119
#57 call_function (oparg=<optimized out>, pp_stack=0x7fffffffbf50) at Python/ceval.c:4054
#58 PyEval_EvalFrameEx (f=f@entry=0x12245b20, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#59 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc0d0,
func=<optimized out>) at Python/ceval.c:4119
#60 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc0d0) at Python/ceval.c:4054
#61 PyEval_EvalFrameEx (f=f@entry=0x17a91d0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#62 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc250,
func=<optimized out>) at Python/ceval.c:4119
#63 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc250) at Python/ceval.c:4054
#64 PyEval_EvalFrameEx (f=f@entry=0xdbf9420, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#65 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc3d0,
func=<optimized out>) at Python/ceval.c:4119
#66 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc3d0) at Python/ceval.c:4054
#67 PyEval_EvalFrameEx (f=f@entry=0x12054c00, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#68 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc550,
func=<optimized out>) at Python/ceval.c:4119
#69 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc550) at Python/ceval.c:4054
#70 PyEval_EvalFrameEx (f=f@entry=0x1190a80, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#71 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc6d0,
func=<optimized out>) at Python/ceval.c:4119
#72 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc6d0) at Python/ceval.c:4054
#73 PyEval_EvalFrameEx (f=f@entry=0x2bdc1b0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#74 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc850,
func=<optimized out>) at Python/ceval.c:4119
#75 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc850) at Python/ceval.c:4054
#76 PyEval_EvalFrameEx (f=f@entry=0x11873b0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#77 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffc9d0,
func=<optimized out>) at Python/ceval.c:4119
#78 call_function (oparg=<optimized out>, pp_stack=0x7fffffffc9d0) at Python/ceval.c:4054
#79 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a1b240, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#80 0x00007ffff7afa33e in PyEval_EvalCodeEx (co=0x7fffe958d3b0, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=3, kws=<optimized out>, kwcount=1, defs=0x7fffe985df28, defcount=1, closure=0x0)
at Python/ceval.c:3265
#81 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=3, n=<optimized out>, pp_stack=0x7fffffffcc00, func=<optimized out>)
at Python/ceval.c:4129
#82 call_function (oparg=<optimized out>, pp_stack=0x7fffffffcc00) at Python/ceval.c:4054
#83 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a20850, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#84 0x00007ffff7afa33e in PyEval_EvalCodeEx (co=0x7fffe9585d30, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=2, kws=<optimized out>, kwcount=1, defs=0x7fffe984bf28, defcount=1, closure=0x0)
at Python/ceval.c:3265
#85 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=2, n=<optimized out>, pp_stack=0x7fffffffce30, func=<optimized out>)
at Python/ceval.c:4129
#86 call_function (oparg=<optimized out>, pp_stack=0x7fffffffce30) at Python/ceval.c:4054
#87 PyEval_EvalFrameEx (f=f@entry=0x7fffe89ffe18, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#88 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffcfb0,
func=<optimized out>) at Python/ceval.c:4119
#89 call_function (oparg=<optimized out>, pp_stack=0x7fffffffcfb0) at Python/ceval.c:4054
#90 PyEval_EvalFrameEx (f=f@entry=0x7fffe88a55f0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#91 0x00007ffff7afa33e in PyEval_EvalCodeEx (co=0x7fffe9585130, globals=<optimized out>, locals=locals@entry=0x0,
args=<optimized out>, argcount=argcount@entry=3, kws=<optimized out>, kwcount=1, defs=0x7fffe9546b28, defcount=1, closure=0x0)
at Python/ceval.c:3265
#92 0x00007ffff7af3dc4 in fast_function (nk=<optimized out>, na=3, n=<optimized out>, pp_stack=0x7fffffffd1e0, func=<optimized out>)
at Python/ceval.c:4129
#93 call_function (oparg=<optimized out>, pp_stack=0x7fffffffd1e0) at Python/ceval.c:4054
#94 PyEval_EvalFrameEx (f=f@entry=0x1171a70, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#95 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffd360,
func=<optimized out>) at Python/ceval.c:4119
#96 call_function (oparg=<optimized out>, pp_stack=0x7fffffffd360) at Python/ceval.c:4054
#97 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a107d0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#98 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffd4e0,
func=<optimized out>) at Python/ceval.c:4119
#99 call_function (oparg=<optimized out>, pp_stack=0x7fffffffd4e0) at Python/ceval.c:4054
#100 PyEval_EvalFrameEx (f=f@entry=0x7fffe8a52b00, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#101 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffd660,
func=<optimized out>) at Python/ceval.c:4119
#102 call_function (oparg=<optimized out>, pp_stack=0x7fffffffd660) at Python/ceval.c:4054
#103 PyEval_EvalFrameEx (f=f@entry=0x7686d0, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#104 0x00007ffff7af5b5e in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>, pp_stack=0x7fffffffd7e0,
func=<optimized out>) at Python/ceval.c:4119
#105 call_function (oparg=<optimized out>, pp_stack=0x7fffffffd7e0) at Python/ceval.c:4054
#106 PyEval_EvalFrameEx (f=f@entry=0x7ffff7f72050, throwflag=throwflag@entry=0) at Python/ceval.c:2679
#107 0x00007ffff7afa33e in PyEval_EvalCodeEx (co=co@entry=0x7ffff7e71e30, globals=globals@entry=0x7ffff7f5f168,
locals=locals@entry=0x7ffff7f5f168, args=args@entry=0x0, argcount=argcount@entry=0, kws=kws@entry=0x0, kwcount=kwcount@entry=0,
defs=defs@entry=0x0, defcount=defcount@entry=0, closure=closure@entry=0x0) at Python/ceval.c:3265
#108 0x00007ffff7b27142 in PyEval_EvalCode (co=co@entry=0x7ffff7e71e30, globals=globals@entry=0x7ffff7f5f168,
locals=locals@entry=0x7ffff7f5f168) at Python/ceval.c:673
#109 0x00007ffff7b338ad in run_mod (mod=mod@entry=0x6c6670, filename=filename@entry=0x7fffffffe113 "/usr/bin/log2timeline.py",
globals=globals@entry=0x7ffff7f5f168, locals=locals@entry=0x7ffff7f5f168, flags=flags@entry=0x7fffffffda30,
arena=arena@entry=0x635c70) at Python/pythonrun.c:1377
#110 0x00007ffff7ac16ad in PyRun_FileExFlags (fp=fp@entry=0x635a20,
filename=filename@entry=0x7fffffffe113 "/usr/bin/log2timeline.py", start=start@entry=257, globals=globals@entry=0x7ffff7f5f168,
locals=locals@entry=0x7ffff7f5f168, closeit=closeit@entry=1, flags=flags@entry=0x7fffffffda30) at Python/pythonrun.c:1363
#111 0x00007ffff7ac2294 in PyRun_SimpleFileExFlags (fp=fp@entry=0x635a20, filename=<optimized out>,
filename@entry=0x7fffffffe113 "/usr/bin/log2timeline.py", closeit=closeit@entry=1, flags=flags@entry=0x7fffffffda30)
at Python/pythonrun.c:955
#112 0x00007ffff7ac27ce in PyRun_AnyFileExFlags (fp=fp@entry=0x635a20,
filename=filename@entry=0x7fffffffe113 "/usr/bin/log2timeline.py", closeit=closeit@entry=1, flags=flags@entry=0x7fffffffda30)
at Python/pythonrun.c:759
#113 0x00007ffff7ac9e63 in Py_Main (argc=<optimized out>, argv=0x7fffffffdbe8) at Modules/main.c:640
#114 0x00007ffff7488b05 in __libc_start_main (main=0x400760 <main>, argc=10, argv=0x7fffffffdbe8, init=<optimized out>,
fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffdbd8) at libc-start.c:285
#115 0x000000000040078e in _start () at ../sysdeps/x86_64/start.S:122What is the last 4.1 in libtsk10-4.1.3-4.1.x86_64 ?
joachimmetz
commented
9 years ago BTW which version of TSK are you using?
In the stock version of sleuthkit-4.1.3, tsk/fs/hfs.c:3257
free(rawBuf);Not hfs_file_read_special as your version indicates:
#4 0x00007ffff02c5045 in hfs_file_read_special (a_fs_attr=, a_offset=,
a_buf=0x7fffdd38d034 "%PDF-1.4\r%\342\343\317\323\r\n480 0 obj\r<>\rendobj\r \rxref\r480 473\r0000000016 00000 n\r\n0000010946 00000 n\r\n0000011190 00000 n\r\n0000011252 "...,
a_len=) at hfs.c:3257Forget the last comment, I'm not paying attention ;)
joachimmetz
commented
9 years ago tsk/fs/hfs.c:3007
// Allocate two buffers of the compression unit size.
rawBuf = (char *) tsk_malloc(COMPRESSION_UNIT_SIZE);tsk/fs/hfs.c:3143
uint32_t len = offsetTable[indx].length;tsk/fs/hfs.c:3156
// Read in the chunk of compressed data
attrReadResult = tsk_fs_attr_read(rAttr, offset,
rawBuf, len, TSK_FS_FILE_READ_FLAG_NONE);So no bounds check of len here before usage.
tsk/fs/hfs.c:3211
if ((len - 1) > COMPRESSION_UNIT_SIZE) {
...
}
memcpy(uncBuf, rawBuf + 1, len - 1);If len is 0 that will yield to interesting behavior here.
So not unlikely that there is a memory corruption bug here somewhere.
joachimmetz
commented
9 years ago Can you try running valgrind with fls (to be verbose fls -r) on this file system, just to be sure one of these erroneous code paths is triggered.
joachimmetz
commented
9 years ago joachimmetz
commented
9 years ago FYI added some basic gdb info to https://sites.google.com/a/kiddaland.net/plaso/developer/troubleshooting, in case it is needed in the future.
joachimmetz
commented
9 years ago Suggested work around:
joachimmetz
commented
9 years ago Marking as wontfix because this appears to be a bug upstream.
gregfreemyer
commented
9 years ago Looks like you found what you need, but I'll try to answer all here anyway:
What is the last 4.1 in libtsk10-4.1.3-4.1.x86_64 ?
Just a internal build number. Apparently I have commited the spec file or other item 4 times. And that spec file was used one time to build the library.
BTW which version of TSK are you using?
sleuthkit-4.1.3-4.1.x86_64
Filed: sleuthkit/sleuthkit#383
Great
Can you try running valgrind with fls on this file system, just to be sure one of these erroneous code paths is triggered.
I'll give it a shot, but I've never used valgrind.
Suggested work around: mount the file system with the Linux hfs drivers run log2timeline on the mount point
I'll do that, thanks
joachimmetz
commented
9 years ago Looks like you found what you need
Largely yes, but having valgrind confirm it would be nice ;)
gregfreemyer
commented
9 years ago Largely yes, but having valgrind confirm it would be nice ;)
I've been valgrinding for 2 hours. I hope all I needed to do was:
valgrind fls -o 409640 -r CU01/AV155_CU01C1.E01
joachimmetz
commented
9 years ago Yes that is fine for now, see if it mentions memory corruption errors.
gregfreemyer
commented
9 years ago I don't know what you expected it to output, but here's the results.
Note 1: This was a 1TB image that compressed down to 500 GB, thus relatively large. It is from an actual case, so the mix of data is unknown.
Note 2: it took about 12 hours to run through, so I can try with different valgrind options overnight tonight if you like.
> valgrind fls -o 409640 -r CU01/*.E01 > valgrind-fls.out
==29226== Memcheck, a memory error detector
==29226== Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al.
==29226== Using Valgrind-3.10.0 and LibVEX; rerun with -h for copyright info
==29226== Command: fls -o 409640 -r CU01/AV155_CU01C1.E01
==29226==
==29226==
==29226== HEAP SUMMARY:
==29226== in use at exit: 1,344,109,921 bytes in 1,008,643 blocks
==29226== total heap usage: 140,158,148 allocs, 139,149,505 frees, 1,233,199,851,360 bytes allocated
==29226==
==29226== LEAK SUMMARY:
==29226== definitely lost: 1,315,625,139 bytes in 1,002,502 blocks
==29226== indirectly lost: 28,353,795 bytes in 6,124 blocks
==29226== possibly lost: 127,907 bytes in 16 blocks
==29226== still reachable: 3,080 bytes in 1 blocks
==29226== suppressed: 0 bytes in 0 blocks
==29226== Rerun with --leak-check=full to see details of leaked memory
==29226==
==29226== For counts of detected and suppressed errors, rerun with: -v
==29226== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)I don't know what you expected it to output, but here's the results.
Not really, was hoping to see invalid read/write warnings. So maybe the bug is triggered somewhere else. I try to think of alternative trouble shooting options.
It is from an actual case, so the mix of data is unknown
That's why I asked you to run fls ;) Limit the test to the file system first.
it took about 12 hours to run through
Yes running with valgrind is not the fastest option, but then again it is thorough in what it supposed to do, namely checking for memory errors.
gregfreemyer
commented
9 years ago My impression is it happens in the first hour or two of log2timeline.py processing.
What if over the weekend I start it up and let it run. Even inside valgrind it should get that far by Monday. Then if I see the stacktrace I just kill valgrind?
If that is what is desired, please let me know the valgrind options you want me to run it with.
joachimmetz
commented
9 years ago The problem with running python in valgrind is that it will give a lot of noise because how the Python memory allocator works. It is possible that valgrind prevents the stack trace from happening. You can give it a try, but store it in a log file since there will probably a lot of log messages.
joachimmetz
commented
9 years ago Needs further analysis and likely a fix in libtsk.
kiddinn
commented
9 years ago is this something we want to continue having open as a plaso issue or should we close this as this is most likely an issue with TSK?
joachimmetz
commented
9 years ago Closing this one, already marked as wontfix.
This is a 500GB image from a recent generation Mac Book Pro running Mavericks.
Processing the image continues, so this s a minor issue. Nothing in the backtrace seems related to log2timeline, so I I wonder if something stomped on memory it should not have? (Can that happen in python?)
Standard invocation: