Hugo: Hugo server crashes when lots of content files change within a short period of time

Created on 10 Aug 2019  路  3Comments  路  Source: gohugoio/hugo

I programatically delete and regenerate directories and markdown files. Running Hugo server at the same time often causes Hugo v0.56.3/extended windows/amd64 to crash. Here ist the log:

Change detected, rebuilding site.
2019-08-10 15:41:46.114 +0200
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\44\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\47\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\55\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\56\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\96\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\108\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\122\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\129\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\147\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\204\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\205\\index.md": CREATE
Total in 90 ms
adding created directory to watchlist C:\Hugo\example.com\content\en\cities\230
adding created directory to watchlist C:\Hugo\example.com\content\en\cities\234
adding created directory to watchlist C:\Hugo\example.com\content\en\cities\239
adding created directory to watchlist C:\Hugo\example.com\content\en\cities\271
adding created directory to watchlist C:\Hugo\example.com\content\de\countries
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\1
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\19
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\22
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\33
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\4
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\6
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\77
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\83
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\9
adding created directory to watchlist C:\Hugo\example.com\content\de\countries\98
adding created directory to watchlist C:\Hugo\example.com\content\de\regions
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\10
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\11
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\17
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\2
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\20
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\23
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\25
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\5
adding created directory to watchlist C:\Hugo\example.com\content\de\regions\7

Change detected, rebuilding site.
2019-08-10 15:41:47.121 +0200
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\230\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\234\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\239\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\en\\cities\\271\\index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\de\\countries\\1\\_index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\de\\countries\\19\\_index.md": CREATE
Source changed "C:\\Hugo\\example.com\\content\\de\\countries\\22\\_index.md": CREATE
[signal 0xc0000005 code=0x0 addr=0x48 pc=0x132c647]

goroutine 290 [running]:
github.com/gohugoio/hugo/commands.(*staticSyncer).isStatic(...)
        /root/project/hugo/commands/static_syncer.go:36
github.com/gohugoio/hugo/commands.(*commandeer).handleEvents.func2(0xc001bcfec0, 0x37, 0x1ce5e00, 0xc001c78e20, 0x0, 0x0, 0xc001ac1738, 0x58b3b5)
        /root/project/hugo/commands/hugo.go:1029 +0x1b7
github.com/gohugoio/hugo/hugofs.(*Walkway).walk(0xc000495710, 0xc001bcfec0, 0x37, 0x1ce5e00, 0xc001c78e20, 0x0, 0x0, 0x0, 0xc0022e7860, 0x0, ...)
        /root/project/hugo/hugofs/walk.go:167 +0x81
github.com/gohugoio/hugo/hugofs.(*Walkway).walk(0xc000495710, 0xc0014186c0, 0x2d, 0x1ce5e00, 0xc001ccb180, 0xc00230d0c0, 0x1, 0x1, 0xc0022e7860, 0x1cb6560, ...)
        /root/project/hugo/hugofs/walk.go:290 +0x777
github.com/gohugoio/hugo/hugofs.(*Walkway).Walk(0xc000495710, 0xc001ccaf60, 0xc0014186c0)
        /root/project/hugo/hugofs/walk.go:137 +0x1e4
github.com/gohugoio/hugo/helpers.SymbolicWalk(0x1cf2680, 0x293a280, 0xc0014186c0, 0x2d, 0xc0022e7860, 0x0, 0x0)
        /root/project/hugo/helpers/path.go:518 +0x11b
github.com/gohugoio/hugo/commands.(*commandeer).handleEvents(0xc000076680, 0xc0018b8e60, 0xc001c6e908, 0xc002258000, 0x26, 0x40, 0xc001ff8000)
        /root/project/hugo/commands/hugo.go:1042 +0x1277
github.com/gohugoio/hugo/commands.(*commandeer).newWatcher.func1(0xc0018b8e60, 0xc000076680, 0xc001c6e908, 0xc001ff8000)
        /root/project/hugo/commands/hugo.go:842 +0x1df
created by github.com/gohugoio/hugo/commands.(*commandeer).newWatcher
        /root/project/hugo/commands/hugo.go:838 +0x295

Schwarz@TSchwarz MINGW64 /c/Hugo/example.com (master)
$ hugo version
Hugo Static Site Generator v0.56.3/extended windows/amd64 BuildDate: unknown
Bug

Most helpful comment

釀夅叧釀忈叧釀呩叺釂剦釁a喓 2019-08-14 釀嬦叐釀掅叜 11 33 06
Hugo Static Site Generator v0.56.3/extended darwin/amd64 BuildDate: unknown

reappearance

$ hugo new site sample
$ cd sample
$ touch create.sh parallel.sh
$ chmod +x create.sh parallel.sh

create.sh:

#!/bin/bash

for (( i = $1 ; i <= $2 ; i++ )); do
    hugo new post/"${i}"/index.md
done

parallel.sh:

#!/bin/bash

$1 1 1000 &
$1 1001 2000 &
$1 2001 3000 &

and open 3 terminals.

  • first : run hugo serve -D
  • second : run ./parallel.sh ./create.sh. the following message is printed: '.../post/$i/index.md'.
  • third : every time $ i changes between 100 and 200, run the following command: rm -rf content/post/*

since this issue is multithreaded, you may need to repeat the command multiple times in the third terminal.

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x60 pc=0x4efbc40]

.....

If the reproduction is successful, you will see the above message. the above appears to be a problem in /root/project/hugo/commands/static_syncer.go:36, but in fact more errors can occur.

cause

first, I checked isStatic() in the static_syncer.go file.

func (s *staticSyncer) isStatic(filename string) bool {
    return s.c.hugo.BaseFs.SourceFilesystems.IsStatic(filename)
}

as the error suggests, the wrong memory reference is the problem. To see this, I added a simple code above return.

if s == nil {
    fmt.Println("sync is nil")
} else if s.c == nil {
    fmt.Println("commandeer is nil")
} else if s.c.hugo == nil {
    fmt.Println("hugo is nil")
} else if s.c.hugo.BaseFs == nil {
    fmt.Println("basefs is nil")
} else if s.c.hugo.BaseFs.SourceFilesystems == nil {
    fmt.Println("source file system is nil")
}

The result is hugo is nil. Follow the code a little bit and you will see that the field is in commandeerHugoState.

If this field is nil:

  1. commandeer changed: In this case, commandeer is nil would have been output in the if statement.
  2. commandeerHugoState changed: Assigned in two places. commandeer.go, hugo.go
  3. commandeerHugoState.hugo changed: Assigned from commandeer.go

I checked if nil is assigned in commandeerHugoState.hugo, but the sample didn't have that problem.

If you look at the code a little bit further, you can see that all three of these things run on different goroutines.

At this point, commandeerHugoState.hugo initialization always runs after commandeerHugoState reallocation. however, commandeerHugoState.hugo access is independent of other goroutines.

In this case, this problem occurs when each goroutine is executed in the following order.

  1. reassign commandeerHugoState
  2. __access commandeerHugoState.hugo (is nil, panic)__
  3. initialize commandeerHugoState.hugo

All 3 comments

Is there a repo that can be used to reproduce this?

Sorry, I can't provide a repo to reproduce. I'm currently to busy to set something up.

釀夅叧釀忈叧釀呩叺釂剦釁a喓 2019-08-14 釀嬦叐釀掅叜 11 33 06
Hugo Static Site Generator v0.56.3/extended darwin/amd64 BuildDate: unknown

reappearance

$ hugo new site sample
$ cd sample
$ touch create.sh parallel.sh
$ chmod +x create.sh parallel.sh

create.sh:

#!/bin/bash

for (( i = $1 ; i <= $2 ; i++ )); do
    hugo new post/"${i}"/index.md
done

parallel.sh:

#!/bin/bash

$1 1 1000 &
$1 1001 2000 &
$1 2001 3000 &

and open 3 terminals.

  • first : run hugo serve -D
  • second : run ./parallel.sh ./create.sh. the following message is printed: '.../post/$i/index.md'.
  • third : every time $ i changes between 100 and 200, run the following command: rm -rf content/post/*

since this issue is multithreaded, you may need to repeat the command multiple times in the third terminal.

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x60 pc=0x4efbc40]

.....

If the reproduction is successful, you will see the above message. the above appears to be a problem in /root/project/hugo/commands/static_syncer.go:36, but in fact more errors can occur.

cause

first, I checked isStatic() in the static_syncer.go file.

func (s *staticSyncer) isStatic(filename string) bool {
    return s.c.hugo.BaseFs.SourceFilesystems.IsStatic(filename)
}

as the error suggests, the wrong memory reference is the problem. To see this, I added a simple code above return.

if s == nil {
    fmt.Println("sync is nil")
} else if s.c == nil {
    fmt.Println("commandeer is nil")
} else if s.c.hugo == nil {
    fmt.Println("hugo is nil")
} else if s.c.hugo.BaseFs == nil {
    fmt.Println("basefs is nil")
} else if s.c.hugo.BaseFs.SourceFilesystems == nil {
    fmt.Println("source file system is nil")
}

The result is hugo is nil. Follow the code a little bit and you will see that the field is in commandeerHugoState.

If this field is nil:

  1. commandeer changed: In this case, commandeer is nil would have been output in the if statement.
  2. commandeerHugoState changed: Assigned in two places. commandeer.go, hugo.go
  3. commandeerHugoState.hugo changed: Assigned from commandeer.go

I checked if nil is assigned in commandeerHugoState.hugo, but the sample didn't have that problem.

If you look at the code a little bit further, you can see that all three of these things run on different goroutines.

At this point, commandeerHugoState.hugo initialization always runs after commandeerHugoState reallocation. however, commandeerHugoState.hugo access is independent of other goroutines.

In this case, this problem occurs when each goroutine is executed in the following order.

  1. reassign commandeerHugoState
  2. __access commandeerHugoState.hugo (is nil, panic)__
  3. initialize commandeerHugoState.hugo
Was this page helpful?
0 / 5 - 0 ratings

Related issues

crash-dive picture crash-dive  路  3Comments

ianbrandt picture ianbrandt  路  3Comments

nikolas picture nikolas  路  3Comments

antifuchs picture antifuchs  路  3Comments

digitalcraftsman picture digitalcraftsman  路  3Comments