Segfault when SIGINT interrupts scan

[vs49688]

Description

A fresh Navidrome installation segfaults after receiving a SIGINT.

Expected Behaviour

Not to segfault.

Steps to reproduce

1. Run navidrome in an empty folder.
2. Wait for Navidrome server is ready!
3. Send SIGINT (or Ctrl+C)
4. Observe segfault

Platform information

• Navidrome version: v0.49.0
• Browser and version: N/A
• Operating System: NixOS 23.05.20230120.5ed4819 (Stoat)

Additional information

Seems to occur when interrupting the scanner.

INFO[0000] Mounting Public Endpoints routes              path=/share
INFO[0000] Mounting LastFM Auth routes                   path=/api/lastfm
INFO[0000] Mounting ListenBrainz Auth routes             path=/api/listenbrainz
INFO[0000] Mounting Background images routes             path=/backgrounds
INFO[0000] Mounting WebUI routes                         path=/app
INFO[0000] Navidrome server is ready!                    address="0.0.0.0:4533" startupTime=158.6ms
^CINFO[0000] Received termination signal                   signal=interrupt
INFO[0001] Stopping HTTP server                         
ERRO[0002] Error stating dir                             error="stat music: no such file or directory" path=music
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x5c pc=0xc2386d]

goroutine 74 [running]:
github.com/navidrome/navidrome/scanner.isDirEmpty({0x23af030?, 0xc0006e45a0?}, {0xc000355db7?, 0xc000388dc8?})
        github.com/navidrome/navidrome/scanner/tag_scanner.go:171 +0x2d
github.com/navidrome/navidrome/scanner.(*TagScanner).Scan(0xc0004631d0, {0x23aef88?, 0xc00028b980?}, {0x5?, 0x5?, 0x0?}, 0x0?)
        github.com/navidrome/navidrome/scanner/tag_scanner.go:85 +0x15a
github.com/navidrome/navidrome/scanner.(*scanner).rescan(0xc000208c00, {0x23aef88?, 0xc00028b980}, {0xc000355db7, 0x5}, 0x0)
        github.com/navidrome/navidrome/scanner/scanner.go:92 +0x3d6
github.com/navidrome/navidrome/scanner.(*scanner).RescanAll(0xc000208c00, {0x23aef88, 0xc00028b980}, 0x1?)
        github.com/navidrome/navidrome/scanner/scanner.go:149 +0x1d3
github.com/navidrome/navidrome/cmd.schedulePeriodicScan.func1()
        github.com/navidrome/navidrome/cmd/root.go:127 +0x25b
golang.org/x/sync/errgroup.(*Group).Go.func1()
        golang.org/x/sync@v0.1.0/errgroup/errgroup.go:75 +0x64
created by golang.org/x/sync/errgroup.(*Group).Go
        golang.org/x/sync@v0.1.0/errgroup/errgroup.go:72 +0xa5

[deluan]

I can't seem to reproduce this locally. Is this happening consistently? And the lines in the stack trace does not make sense (tag_scanner:85 does not call tag_scanner:177 code, line 177 is not in isDirEmpty). Is this one of your branches? I'd need to see the source code that caused this issue.

[vs49688]

That's because I'm a dingus and filed this bug report really late at night. It was on a branch, but I've repro'd this on vanilla v0.49.0 and updated the stack trace.

If you're a Nix user, you can reproduce the broken binary using at https://github.com/vs49688/nix-repo/tree/brokendrome
with nix build .#navidrome-mbz (it's vanilla Navidrome, I just haven't changed the property name).

[deluan]

I was not able to reproduce it on my side (macOS and Ubuntu), but I put a guard agains the nil pointer error. Can you confirm it works now?

[vs49688]

It's better, it doesn't crash now:

INFO[0000] Mounting Background images routes             path=/backgrounds
INFO[0000] Mounting WebUI routes                         path=/app
INFO[0000] Navidrome server is ready!                    address="0.0.0.0:4533" startupTime=235.1ms
^CINFO[0001] Received termination signal                   signal=interrupt
INFO[0001] Stopping HTTP server
ERRO[0002] Error stating dir                             error="stat music: no such file or directory" path=music
ERRO[0002] Error importing MediaFolder                   error="stat music: no such file or directory" folder=music
ERRO[0002] Errors while scanning media. Please check the logs
ERRO[0002] Error executing initial scan                  error="scan error"
INFO[0002] Closing Database
INFO[0002] Navidrome stopped, bye.

[deluan]

ERRO[0002] Error stating dir                             error="stat music: no such file or directory" path=music
ERRO[0002] Error importing MediaFolder                   error="stat music: no such file or directory" folder=music

Why the music folder is suddenly unavailable when Navidrome receives a SIGINT? That's the part I can't reproduce.... If you don't interrupt it, can you actually see the music?

[vs49688]

There is no music folder, it's a completely blank installation, and I think that's what it's choking on.
This originated from me simply checking if the binary ran after being built.

[zane@MORNINGSTAR:~/Documents/Coding/nix-repo/x] (brokendrome) $ pwd
/home/zane/Documents/Coding/nix-repo/x
[zane@MORNINGSTAR:~/Documents/Coding/nix-repo/x] (brokendrome) $ ls -la
total 8
drwxr-xr-x 2 zane zane 4096 Feb  1 12:35 .
drwxr-xr-x 9 zane zane 4096 Feb  1 12:21 ..
[zane@MORNINGSTAR:~/Documents/Coding/nix-repo/x] (brokendrome) $ ls -la ../result/bin/
total 40280
dr-xr-xr-x 2 root root     4096 Jan  1  1970 .
dr-xr-xr-x 3 root root     4096 Jan  1  1970 ..
-r-xr-xr-x 2 root root      421 Jan  1  1970 navidrome
-r-xr-xr-x 2 root root 41226968 Jan  1  1970 .navidrome-wrapped
[zane@MORNINGSTAR:~/Documents/Coding/nix-repo/x] (brokendrome) $ ND_LOGLEVEL=trace ../result/bin/navidrome
 _   _             _     _
| \ | |           (_)   | |
|  \| | __ ___   ___  __| |_ __ ___  _ __ ___   ___
| . ` |/ _` \ \ / / |/ _` | '__/ _ \| '_ ` _ \ / _ \
| |\  | (_| |\ V /| | (_| | | | (_) | | | | | |  __/
\_| \_/\__,_| \_/ |_|\__,_|_|  \___/|_| |_| |_|\___|
                           Version: 0.49.0 (aaf58bb)

Loaded configuration from '': &conf.configOptions{
    ConfigFile:                       "",
    Address:                          "0.0.0.0",
    Port:                             4533,
    MusicFolder:                      "music",
    DataFolder:                       ".",
    DbPath:                           "navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on",
    LogLevel:                         "trace",
    ScanInterval:                     -1,
    ScanSchedule:                     "@every 1m",
    SessionTimeout:                   86400000000000,
    BaseURL:                          "",
    UILoginBackgroundURL:             "/backgrounds",
    EnableTranscodingConfig:          false,
    EnableDownloads:                  true,
    EnableExternalServices:           true,
    EnableMediaFileCoverArt:          true,
    TranscodingCacheSize:             "100MB",
    ImageCacheSize:                   "100MB",
    AutoImportPlaylists:              true,
    PlaylistsPath:                    ".:**/**",
    AutoTranscodeDownload:            false,
    DefaultDownsamplingFormat:        "opus",
    SearchFullString:                 false,
    RecentlyAddedByModTime:           false,
    IgnoredArticles:                  "The El La Los Las Le Les Os As O A",
    IndexGroups:                      "A B C D E F G H I J K L M N O P Q R S T U V W X-Z(XYZ) [Unknown]([)",
    SubsonicArtistParticipations:     false,
    ProbeCommand:                     "ffmpeg %s -f ffmetadata",
    CoverArtPriority:                 "cover.*, folder.*, front.*, embedded, external",
    CoverJpegQuality:                 75,
    UIWelcomeMessage:                 "",
    EnableGravatar:                   false,
    EnableFavourites:                 true,
    EnableStarRating:                 true,
    EnableUserEditing:                true,
    EnableSharing:                    false,
    DefaultTheme:                     "Dark",
    DefaultLanguage:                  "",
    DefaultUIVolume:                  100,
    EnableReplayGain:                 false,
    EnableCoverAnimation:             true,
    GATrackingID:                     "",
    EnableLogRedacting:               true,
    AuthRequestLimit:                 5,
    AuthWindowLength:                 20000000000,
    PasswordEncryptionKey:            "[REDACTED]",
    ReverseProxyUserHeader:           "Remote-User",
    ReverseProxyWhitelist:            "",
    Prometheus:                       conf.prometheusOptions{Enabled:false, MetricsPath:"/metrics"},
    Scanner:                          conf.scannerOptions{Extractor:"taglib", GenreSeparators:";/,"},
    Agents:                           "lastfm,spotify",
    LastFM:                           conf.lastfmOptions{Enabled:true, ApiKey:"[REDACTED]", Secret:"[REDACTED]", Language:"en"},
    Spotify:                          conf.spotifyOptions{},
    ListenBrainz:                     conf.listenBrainzOptions{Enabled:true, BaseURL:"https://api.listenbrainz.org/1/"},
    DevLogSourceLine:                 false,
    DevLogLevels:                     {},
    DevAutoCreateAdminPassword:       "",
    DevAutoLoginUsername:             "",
    DevActivityPanel:                 true,
    DevSidebarPlaylists:              true,
    DevEnableBufferedScrobble:        true,
    DevShowArtistPage:                true,
    DevArtworkMaxRequests:            8,
    DevArtworkThrottleBacklogLimit:   100,
    DevArtworkThrottleBacklogTimeout: 60000000000,
}
DEBU[0000] Opening DataBase                              dbPath="navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on" driver=sqlite3
TRAC[0000] Created new singleton                         instance="&{waitDuration:0 connector:{dsn:navidrome.db?cache=shared&_busy_timeout=15000&_journal_mode=WAL&_foreign_keys=on driver:0xc00045fb80} numClosed:0 mu:{state:0 sema:0} freeConn:[] connRequests:map[] nextRequest:0 numOpen:0 openerCh:0xc000042cc0 closed:false dep:map[] lastPut:map[] maxIdleCount:0 maxOpen:0 maxLifetime:0 maxIdleTime:0 cleanerCh:<nil> waitCount:0 maxIdleClosed:0 maxIdleTimeClosed:0 maxLifetimeClosed:0 stop:0x4a2e80}" type="*sql.DB"
INFO[0000] Creating DB Schema
INFO[0000] Starting signaler
TRAC[0000] Created new singleton                         instance="&{FileCache:0xc00028e2a0}" type="*artwork.imageCache"
INFO[0000] Setting Session Timeout                       value=24h
ERRO[0000] Agent not available. Check configuration      name=spotify
INFO[0000] Creating Image cache                          maxSize="100 MB" path=cache/images
TRAC[0000] Created new singleton                         instance="&{publish:0xc00028e360 subscribing:0xc00028e3c0 unsubscribing:0xc00028e480}" type="*events.broker"
TRAC[0000] SQL: `SELECT value FROM property WHERE id = ?`  args="['JWTSecret']" elapsedTime="68.821µs" rowsAffected=0
DEBU[0000] Loaded cache                                  dir=cache/images numItems=0
INFO[0000] Finished initializing cache                   cache=Image elapsedTime="323.322µs" maxSize=100MB
INFO[0000] Configuring Media Folder                      name="Music Library" path=music
TRAC[0000] SQL: `SELECT value FROM property WHERE id = ?`  args="['LastScan-music']" elapsedTime="43.923µs" rowsAffected=0
INFO[0000] Starting scheduler
TRAC[0000] Created new singleton                         instance="&{c:0xc00041c1e0}" type="*scheduler.scheduler"
INFO[0000] Scheduling periodic scan                      schedule="@every 1m"
TRAC[0000] SQL: `SELECT value FROM property WHERE id = ?`  args="['InitialSetup']" elapsedTime="43.249µs" rowsAffected=0
INFO[0000] Running initial setup
TRAC[0000] SQL: `SELECT value FROM property WHERE id = ?`  args="['JWTSecret']" elapsedTime="85.18µs" rowsAffected=0
DEBU[0000] Scheduler: start
INFO[0000] Creating new JWT secret, used for encrypting UI sessions
DEBU[0000] Scheduler: added                              entry=1 next="2023-02-01 12:36:58 +1000 AEST" now="2023-02-01 12:35:58.738430031 +1000 AEST"
TRAC[0000] SQL: `UPDATE property SET value = ? WHERE id = ?`  args="['15a8f6be-0d27-482f-8981-86ca4105356c','JWTSecret']" elapsedTime="68.721µs" rowsAffected=0
TRAC[0000] SQL: `INSERT INTO property (id,value) VALUES (?,?)`  args="['JWTSecret','15a8f6be-0d27-482f-8981-86ca4105356c']" elapsedTime="102.222µs" rowsAffected=1
TRAC[0000] SQL: `UPDATE property SET value = ? WHERE id = ?`  args="['2023-02-01 12:35:58.738875549 +1000 AEST m=+0.225949185','InitialSetup']" elapsedTime="62.469µs" rowsAffected=0
TRAC[0000] SQL: `INSERT INTO property (id,value) VALUES (?,?)`  args="['InitialSetup','2023-02-01 12:35:58.738875549 +1000 AEST m=+0.225949185']" elapsedTime="73.192µs" rowsAffected=1
INFO[0000] Login rate limit set                          requestLimit=5 windowLength=20s
INFO[0000] Found ffmpeg                                  path=/nix/store/zhq625lb0pcl2w772rhwlfy94phz10g2-ffmpeg-4.4.2-bin/bin/ffmpeg
DEBU[0000] Last.fm integration is ENABLED
DEBU[0000] ListenBrainz integration is ENABLED           ListenBrainz.BaseURL="https://api.listenbrainz.org/1/"
INFO[0000] Spotify integration is not enabled: missing ID/Secret
INFO[0000] Mounting Native API routes                    path=/api
ERRO[0000] Agent not available. Check configuration      name=spotify
INFO[0000] Creating Transcoding cache                    maxSize="100 MB" path=cache/transcoding
TRAC[0000] Created new singleton                         instance="&{ds:0xc000135080 broker:0xc00037ce88 playMap:0xc000140600 scrobblers:map[lastfm:0xc0007cd280 listenbrainz:0xc0007cd2c0]}" type="*scrobbler.playTracker"
DEBU[0000] Loaded cache                                  dir=cache/transcoding numItems=0
INFO[0000] Finished initializing cache                   cache=Transcoding elapsedTime="362.622µs" maxSize=100MB
TRAC[0000] SQL: `SELECT user_id FROM scrobble_buffer WHERE (service = ?) GROUP BY user_id ORDER BY count(*)`  args="['listenbrainz']" elapsedTime="182.4µs" rowsAffected=0
TRAC[0000] SQL: `SELECT user_id FROM scrobble_buffer WHERE (service = ?) GROUP BY user_id ORDER BY count(*)`  args="['lastfm']" elapsedTime="229.15µs" rowsAffected=0
INFO[0000] Mounting Subsonic API routes                  path=/rest
ERRO[0000] Agent not available. Check configuration      name=spotify
INFO[0000] Mounting Public Endpoints routes              path=/share
INFO[0000] Mounting LastFM Auth routes                   path=/api/lastfm
INFO[0000] Mounting ListenBrainz Auth routes             path=/api/listenbrainz
INFO[0000] Mounting Background images routes             path=/backgrounds
INFO[0000] Mounting WebUI routes                         path=/app
INFO[0000] Navidrome server is ready!                    address="0.0.0.0:4533" startupTime=226.8ms
DEBU[0000] Loaded images from image service              elapsed=148.7ms total=88
^CINFO[0001] Received termination signal                   signal=interrupt
INFO[0001] Stopping HTTP server
DEBU[0001] Scheduler: stop
DEBU[0002] Executing initial scan
TRAC[0002] SQL: `SELECT value FROM property WHERE id = ?`  args="['LastScan-music']" elapsedTime="207.749µs" rowsAffected=0
DEBU[0002] Scanning folder                               folder=music lastModifiedSince="0001-01-01 00:00:00 +0000 UTC"
TRAC[0002] Broker received new event                     event="{0 scanStatus {\"scanning\":true,\"count\":0,\"folderCount\":0} 0xc000067dc0}"
TRAC[0002] Got new published event                       event="{1 scanStatus {\"scanning\":true,\"count\":0,\"folderCount\":0} 0xc000067dc0}"
TRAC[0002] SQL: `SELECT * FROM user WHERE is_admin = ? ORDER BY updated_at asc LIMIT 1`  args="[true]" elapsedTime="331.508µs" rowsAffected=0
TRAC[0002] SQL: `SELECT count(distinct user.id) as count FROM user`  args="[]" elapsedTime="142.927µs" rowsAffected=1
DEBU[0002] Scanner: No admin user yet!
ERRO[0002] Error stating dir                             error="stat music: no such file or directory" path=music
ERRO[0002] Error importing MediaFolder                   error="stat music: no such file or directory" folder=music
TRAC[0002] SQL: `UPDATE property SET value = ? WHERE id = ?`  args="['1675218960739','LastScan-music']" elapsedTime="110.785µs" rowsAffected=0
TRAC[0002] SQL: `INSERT INTO property (id,value) VALUES (?,?)`  args="['LastScan-music','1675218960739']" elapsedTime="202.899µs" rowsAffected=1
ERRO[0002] Errors while scanning media. Please check the logs
TRAC[0002] Broker received new event                     event="{0 scanStatus {\"scanning\":false,\"count\":0,\"folderCount\":0} 0xc000067dc0}"
TRAC[0002] Got new published event                       event="{2 scanStatus {\"scanning\":false,\"count\":0,\"folderCount\":0} 0xc000067dc0}"
TRAC[0002] SQL: `SELECT starred, starred_at, play_count, play_date, rating, count(distinct album.id) as count FROM album LEFT JOIN annotation on (annotation.item_id = album.id AND annotation.item_type = 'album' AND annotation.user_id = '-1') LEFT JOIN album_genres ag on album.id = ag.album_id LEFT JOIN genre on ag.genre_id = genre.id`  args="[]" elapsedTime="302.989µs" rowsAffected=1
TRAC[0002] SQL: `SELECT starred, starred_at, play_count, play_date, rating, count(distinct media_file.id) as count FROM media_file LEFT JOIN annotation on (annotation.item_id = media_file.id AND annotation.item_type = 'media_file' AND annotation.user_id = '-1') LEFT JOIN media_file_genres ag on media_file.id = ag.media_file_id LEFT JOIN genre on ag.genre_id = genre.id`  args="[]" elapsedTime="235.837µs" rowsAffected=1
TRAC[0002] SQL: `SELECT count(distinct user.id) as count FROM user`  args="[]" elapsedTime="134.482µs" rowsAffected=1
ERRO[0002] Error executing initial scan                  error="scan error"
DEBU[0002] Finished initial scan
INFO[0002] Closing Database
INFO[0002] Navidrome stopped, bye.

[vs49688]

If I mkdir music all this goes away apparently -.-

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.