svn 1586 crashed when scan

[yllu]

There are 11 media files in my folder, including 5 wav files, 2 M4V files and 4 mp4 files.
After starting mt-daapd about 3 hours with 1 second rescan-interval, mt-daapd crashed.
The following is the end of the log file with debug level 9.

2007-08-23 14:19:15 (40018260): Rows: 1

2007-08-23 14:19:15 (40018260): Skipping file, not modified

2007-08-23 14:19:15 (40018260): Ending song scan

2007-08-23 14:19:15 (40018260): Executing: pragma synchronous = off

2007-08-23 14:19:15 (40018260): Rows: 1

2007-08-23 14:19:15 (40018260): Executing: begin transaction

2007-08-23 14:19:15 (40018260): Rows: 1

2007-08-23 14:19:15 (40018260): Processing playlists

2007-08-23 14:19:15 (40018260): Starting playlist scan

2007-08-23 14:19:15 (40018260): Finished playlist loop

2007-08-23 14:19:15 (40018260): Executing: end transaction

2007-08-23 14:19:15 (40018260): Rows: 1

2007-08-23 14:19:15 (40018260): Executing: pragma synchronous=normal

2007-08-23 14:19:15 (40018260): Rows: 1

2007-08-23 14:19:15 (40018260): Executing: delete from songs where id not in (select id from updated)

2007-08-23 14:19:15 (40018260): Rows: 0

2007-08-23 14:19:15 (40018260): Executing: update songs set force_update=0

2007-08-23 14:19:15 (40018260): Rows: 11

2007-08-23 14:19:15 (40018260): Executing: drop table updated

2007-08-23 14:19:15 (40018260): Rows: 11

2007-08-23 14:19:15 (40018260): Executing: delete from playlists where ((type=2) OR (type=3)) and id not in (select id from plupdated)

2007-08-23 14:19:15 (40018260): Rows: 0

2007-08-23 14:19:15 (40018260): Executing: delete from playlistitems where playlistid not in (select distinct id from playlists)

2007-08-23 14:19:15 (40018260): Rows: 0

2007-08-23 14:19:15 (40018260): Executing: drop table plupdated

2007-08-23 14:19:15 (40018260): Rows: 0

2007-08-23 14:19:15 (40018260): Updating playlists

2007-08-23 14:19:15 (40018260): Executing: select count(*) from playlists

2007-08-23 14:19:15 (40018260): Executing: select * from playlists

2007-08-23 14:19:15 (40018260): Executing: update playlists set items=(select count(*) from songs where 1) where id=1

2007-08-23 14:19:15 (40018260): Rows: 1

2007-08-23 14:19:15 (40018260): Executing: select count(*) FROM songs

2007-08-23 14:19:15 (40018260): Scanned 11 songs (was 11) in 0 seconds

2007-08-23 14:19:17 (40018260): Rescanning database

2007-08-23 14:19:17 (40018260): Starting scan_init

2007-08-23 14:19:17 (40018260): Starting db scan

2007-08-23 14:19:17 (40018260): Executing: drop table updated

2007-08-23 14:19:17 (40018260): Query: drop table updated

2007-08-23 14:19:17 (40018260): Error: no such table: updated

2007-08-23 14:19:17 (40018260): Executing: create temp table updated (id int)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Executing: drop table plupdated

2007-08-23 14:19:17 (40018260): Query: drop table plupdated

2007-08-23 14:19:17 (40018260): Error: no such table: plupdated

2007-08-23 14:19:17 (40018260): Executing: create temp table plupdated(id int)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Scanning for MP3s in /dev/null

2007-08-23 14:19:17 (40018260): opendir: Not a directory

2007-08-23 14:19:17 (40018260): Scanning for MP3s in /i-data/md0/admin/Test0823

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music

2007-08-23 14:19:17 (40018260): Found Music.. recursing

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music/wav

2007-08-23 14:19:17 (40018260): Found wav.. recursing

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music/wav/imonBeep.wav

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Music/wav/imonBeep.wav' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (1)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music/wav/sonata a major - alla turca - allegretto.wav

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Music/wav/sonata a major - alla turca - allegretto.wav' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (2)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music/wav/48kHz mo 16bit PCM.wav

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Music/wav/48kHz mo 16bit PCM.wav' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (3)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music/wav/16kHz st 16bit PCM.wav

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Music/wav/16kHz st 16bit PCM.wav' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (4)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Music/wav/44.1kHz mo 16bit PCM.wav

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Music/wav/44.1kHz mo 16bit PCM.wav' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (5)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video

2007-08-23 14:19:17 (40018260): Found Video.. recursing

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/M4V

2007-08-23 14:19:17 (40018260): Found M4V.. recursing

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/M4V/720p_VideoOnly.m4v

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Video/M4V/720p_VideoOnly.m4v' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (6)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/M4V/news_sif_1m.m4v

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Video/M4V/news_sif_1m.m4v' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (7)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/MP4

2007-08-23 14:19:17 (40018260): Found MP4.. recursing

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/MP4/Trek2_C_1Mb.mp4

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Video/MP4/Trek2_C_1Mb.mp4' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (8)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/MP4/Stig_V_1500_Shanghai.mp4

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Video/MP4/Stig_V_1500_Shanghai.mp4' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (9)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/MP4/SONY P800 Motorola A835 - Budweiser (Nude Ferret).mp4

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Video/MP4/SONY P800 Motorola A835 - Budweiser (Nude Ferret).mp4' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (10)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Found /i-data/0add4eca/admin/Test0823/Video/MP4/SONY P800 - MP4 VIDEO - Nike - Football - The Mission.mp4

2007-08-23 14:19:17 (40018260): Executing: select * from songs where path='/i-data/0add4eca/admin/Test0823/Video/MP4/SONY P800 - MP4 VIDEO - Nike - Football - The Mission.mp4' and idx=0

2007-08-23 14:19:17 (40018260): Executing: INSERT INTO updated VALUES (11)

2007-08-23 14:19:17 (40018260): Rows: 1

2007-08-23 14:19:17 (40018260): Skipping file, not modified

2007-08-23 14:19:17 (40018260): Processing rendezvous message

2007-08-23 14:19:17 (40018260): Rendezvous socket closed (daap server crashed?) Aborting.

2007-08-23 14:19:17: Aborting

Are there any non-supported files between these 11 files? Or it’s mt-daapd’s bug?
Thanks for solutions.

[fizze]

First of all a rescan interval of 1sec does not seem sane to me 😉

Secondly, those look like mp4 video files, which Im not sure firefly even serves.

If you’re on windows on a decent PC, you can safely set the rescan interval to, say, 600 seconds (10 minutes). You might as well just enable “always_scan” in the ini file rather than force it to do a rescan every other second.

I guess the filescanner hickups when it iterates that fast.

[rpedde]

@fizze wrote:

First of all a rescan interval of 1sec does not seem sane to me 😉

Secondly, those look like mp4 video files, which Im not sure firefly even serves.

If you’re on windows on a decent PC, you can safely set the rescan interval to, say, 600 seconds (10 minutes). You might as well just enable “always_scan” in the ini file rather than force it to do a rescan every other second.

I guess the filescanner hickups when it iterates that fast.

It will serve mp4 after a fashion. But there is something with that specific file that’s making it crap out.

How big is the file? Is it emailable, or is there a link to it on the interwub somewhere?

[yllu]

I use some other files including media and non-media file to run mt-daapd, and changed rescan-interval to 20 seconds.
Here is the end of mt-daapd.log file in one of my test.

2007-08-24 03:43:07 (40018260): Found /_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l

2007-08-24 03:43:07 (40018260): Found J#fPG#l.. recursing

2007-08-24 03:43:07 (40018260): Found /_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l/#v#c

2007-08-24 03:43:07 (40018260): Found /_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l/#v#c.refcount.1

2007-08-24 03:43:07 (40018260): Processing rendezvous message

2007-08-24 03:43:07 (40018260): Rendezvous socket closed (daap server crashed?) Aborting.

2007-08-24 03:43:07: Aborting

I also use strace to get some log at the same time.

03:43:07 lstat64("/_store", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l/#v#c.refcount.1", {st_mode=S_IFREG|0777, st_size=562949953421312, ...}) = 0

03:43:07 time(NULL)                     = 1187898187

03:43:07 write(3, "2007-08-24 03:43:07 (40018260): "..., 150) = 150

03:43:07 write(2, "Found /_store/#u#aBD#j/X5#d#fN/#"..., 118) = 118

03:43:07 stat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l/#v#c.refcount.1", {st_mode=S_IFREG|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l", {st_mode=S_IFDIR|0777, st_size=562949953421312, ...}) = 0

03:43:07 lstat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l/#v#c.refcount.1", {st_mode=S_IFREG|0777, st_size=562949953421312, ...}) = 0

03:43:07 stat64("/_store/#u#aBD#j/X5#d#fN/#oIYO#d/#aT#gB0/J#fPG#l/#v#c.refcount.1", {st_mode=S_IFREG|0777, st_size=562949953421312, ...}) = 0

03:43:07 getdents64(0x15, 0x40b3e028, 0x20000, 0xffffffff) = 0

03:43:07 munmap(0x40b3e000, 135168)     = 0

03:43:07 close(21)                      = 0

03:43:07 getdents64(0x14, 0x40b1d028, 0x20000, 0xffffffff) = 0

03:43:07 munmap(0x40b1d000, 135168)     = 0

03:43:07 close(20)                      = 0

03:43:07 getdents64(0x13, 0x40afc028, 0x20000, 0xffffffff) = 0

03:43:07 --- SIGSEGV (Segmentation fault) @ 0 (0) ---

mt-daapd end up with segmentation fault.

Besides, I found that mt-daapd not always stopped after scanning a specific file.
However, the end of the log is always the same – “Processing rendezvous message. Rendezvous socket closed (daap server crashed?) Aborting.”
And the end of strace log is always the same too.
It seems like program’s bug, not due to non-supported file.

[yllu]

The 4 MP4 files mentioned in the first test are
http://totoro.cs.nthu.edu.tw/~phlee/mp4.rar

[rpedde]

@yllu wrote:

Besides, I found that mt-daapd not always stopped after scanning a specific file.
However, the end of the log is always the same – “Processing rendezvous message. Rendezvous socket closed (daap server crashed?) Aborting.”
And the end of strace log is always the same too.
It seems like program’s bug, not due to non-supported file.

Ya, sure does.

That’s not a real directory, is it? Or is that some kind of multibyte codepage?

And what kind system and os is it? Looks 64-bit right? Is it Solaris, by any chance?

[yllu]

OS is Linux arm. Kernel version is 2.6.18.6.
The testing files are created by Memeo auto backup.
I’m not sure what format Memeo is using for its directory structure.

[yllu]

I ran another test with only 2 m4v files that I mentioned above.
It successfaully lasted a weekend (about 3 days).
I tried to make the 2 m4v file name longer.

720p_VideoOnlyabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz.m4v

news_sif_1mabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz.m4v

The test fails after a few hours.
These are some log that I collected from gdb:

0x40152f94 in nanosleep () from /lib/libc.so.6

(gdb) br rend-posix.c:460

Breakpoint 1 at 0x22f4c: file rend-posix.c, line 460.

(gdb) c

Continuing.

Program received signal SIGSEGV, Segmentation fault.

0x4014eb30 in readdir_r () from /lib/libc.so.6

(gdb) bt

#0  0x4014eb30 in readdir_r () from /lib/libc.so.6

#1  0x00012220 in scan_path (path=0xbeff1bb0 "/i-data/bbb56a93/public/LongFile")

at mp3-scanner.c:365

#2  0x0001258c in scan_init (patharray=0x9b288) at mp3-scanner.c:284

#3  0x0000bb00 in main (argc=2, argv=0x0) at main.c:615

(gdb) fr 1

#1  0x00012220 in scan_path (path=0xbeff1bb0 "/i-data/bbb56a93/public/LongFile")

at mp3-scanner.c:365

365             err=readdir_r(current_dir,(struct dirent *)de,&pde);

(gdb) l

360                 return 0;

361             }

362

363             pde=(struct dirent *)&de;

364

365             err=readdir_r(current_dir,(struct dirent *)de,&pde);

366             if(err == -1) {

367                 DPRINTF(E_DBG,L_SCAN,"Error on readdir_r: %sn",strerror(errno));

368                 err=errno;

369                 closedir(current_dir);

(gdb) p pde

$1 = (struct dirent *) 0x0

(gdb) p de

$2 = "30b000001225S)À0000720p_VideoOnlyabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz.m4v", '' , "200^a", '' ...

(gdb) p current_dir

$4 = (DIR *) 0x40a36008

(gdb) print *current_dir

$5 = 

(gdb) print readdir_r

$6 = {} 0x4014ea1c 

Maybe the buffer size of file name or something is not enough and make pde become 0x0.

[rpedde]

@yllu wrote:

365             err=readdir_r(current_dir,(struct dirent *)de,&pde);

Ooof. That’s it.

Should be fixed in next nightly.

— Ron

[yllu]

I tried to set PATH_MAX to 2048.
I also tried to modify line 334 in mp3-scanner.c to set
char de[sizeof(struct dirent) + MAXNAMLEN + 1]; to char de[sizeof(struct dirent) + MAXNAMLEN + 1024];.
However, the tests both failed.
And I can not figure out what’s wrong with line 365 in mp3-scanner.c.

[rpedde]

@yllu wrote:

I tried to set PATH_MAX to 2048.
I also tried to modify line 334 in mp3-scanner.c to set
char de[sizeof(struct dirent) + MAXNAMLEN + 1]; to char de[sizeof(struct dirent) + MAXNAMLEN + 1024];.
However, the tests both failed.
And I can not figure out what’s wrong with line 365 in mp3-scanner.c.

Looks to me like it should be:

err=readdir_r(current_dir,(struct dirent *)&de,&pde);

rather than

err=readdir_r(current_dir,(struct dirent *)de,&pde);

— Ron

[yllu]

Unfortunately, the test still failed after modifying line 365 in mp3-scanner.c.

[yllu]

Do you have any new ideas about the bug? 🙄

[rpedde]

@yllu wrote:

Do you have any new ideas about the bug? 🙄

The only thing I can think is stack limits… does this machine has small stack requirements? I’ve got some patches to reduce stack consumption, but I haven’t applied them yet.

[yllu]

Linux arm OS with 2.6.18 kernel.
And no other memory consumption process is running while mt-daapd is running.
It seems like not the stack issue. 😥

[Author]

Posts