You are here: Home » Topic » svn 1586 crashed when scan

svn 1586 crashed when scan

Viewing 15 posts - 1 through 15 (of 17 total)
  • Author
    Posts
  • #1649
    yllu
    Participant

    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.

    #12156
    fizze
    Participant

    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.

    #12157
    rpedde
    Participant

    @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?

    #12158
    yllu
    Participant

    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.

    #12159
    yllu
    Participant

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

    #12160
    rpedde
    Participant

    @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?

    #12161
    yllu
    Participant

    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.

    #12162
    yllu
    Participant

    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.

    #12163
    rpedde
    Participant

    @yllu wrote:


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

    Ooof. That’s it.

    Should be fixed in next nightly.

    — Ron

    #12164
    yllu
    Participant

    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.

    #12165
    rpedde
    Participant

    @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

    #12166
    yllu
    Participant

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

    #12167
    yllu
    Participant

    Do you have any new ideas about the bug? 🙄

    #12168
    rpedde
    Participant

    @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.

    #12169
    yllu
    Participant

    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. 😥

Viewing 15 posts - 1 through 15 (of 17 total)
  • The forum ‘Nightlies Feedback’ is closed to new topics and replies.