How can I diagnose a "hanging hugo"?

support
1

In the OpenTitan project, we use Hugo to generate documentation. This has worked fine on my computer in the past, but apparently not today!

We download a pre-built binary (v0.71). When I run the main documentation build command:

/src/lr/opentitan/build/docs-hugo/hugo \
  --config /src/lr/opentitan/site/docs/config.toml \
  --destination /src/lr/opentitan/build/docs \
  --contentDir /src/lr/opentitan \
  --layoutDir /src/lr/opentitan/site/docs/layouts

it gets as far as printing Building sites ... and then appears to hang (with 0% CPU usage).

Running under strace shows the process waiting on a futex, but it’s not particularly easy to see what’s going on. Is there anything I can do to find out more about what’s stuck?

Here’s the output of hugo env, in case it helps:

/src/lr/opentitan/build/docs-hugo/hugo env
Hugo Static Site Generator v0.71.0-06150C87/extended linux/amd64 BuildDate: 2020-05-18T16:15:29Z
GOOS="linux"
GOARCH="amd64"
GOVERSION="go1.14.3"
2

Oh, I found the -v command line argument, and see:

INFO 2020/11/19 12:26:24 No translation bundle found for default language "en"
INFO 2020/11/19 12:26:24 Translation func for language en not found, use default.
INFO 2020/11/19 12:26:24 i18n not initialized; if you need string translations, check that you have a bundle in /i18n that matches the site language or the default language.
INFO 2020/11/19 12:26:24 Using config file: 
Building sites … INFO 2020/11/19 12:26:24 syncing static files to /src/lr/opentitan/build/docs/

Not sure whether that’s particularly informative.

3

I use

–debug --path-warnings --templateMetrics --templateMetricsHints --verboseLog > debug.log

to get the information

4

Thanks for the suggestion. I get one more line(!)

/src/lr/opentitan/build/docs-hugo/hugo --config /src/lr/opentitan/site/docs/config.toml --destination /src/lr/opentitan/build/docs --contentDir /src/lr/opentitan --layoutDir /src/lr/opentitan/site/docs/layouts --debug --path-warnings --templateMetrics --templateMetricsHints --verboseLog | tee debug.log
INFO 2020/11/19 12:37:26 No translation bundle found for default language "en"
INFO 2020/11/19 12:37:26 Translation func for language en not found, use default.
INFO 2020/11/19 12:37:26 i18n not initialized; if you need string translations, check that you have a bundle in /i18n that matches the site language or the default language.
INFO 2020/11/19 12:37:26 Using config file: 
Building sites … INFO 2020/11/19 12:37:26 syncing static files to /src/lr/opentitan/build/docs/
DEBUG 2020/11/19 12:37:26 creating alias: /doc/project/hw_stages/ redirecting to https://docs.opentitan.org/doc/project/development_stages/

but I’m not sure that’s particularly helpful!

Incidentally, I realised that I’d forgotten to pass -f to strace, so wasn’t seeing child processes. But there are 10 of them(!), so I’d rather not have to wade through the log to figure out what was waiting on what.

5

One more piece of information: this doesn’t appear to be an issue with a specific version. I see the same behaviour when I run version 0.78.2.

6

If you’re on a Unix box, you could try to kill the hugo process with kill -SIGABRT and post the stack trace here.

7

That’s neat! I’ve never used SIGABRT like that, and it’s very cool to get a Go stack trace.

This is with version 0.78.2:

$ /src/lr/opentitan/build/docs-hugo/hugo env
Hugo Static Site Generator v0.78.2-959724F0/extended linux/amd64 BuildDate: 2020-11-13T10:16:23Z
GOOS="linux"
GOARCH="amd64"
GOVERSION="go1.15.1"

I don’t think I can attach the trace (seemingly the only allowed file types are images), so sorry for the giant pasted log.

SIGABRT: abort
PC=0x530501 m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex(0x3285768, 0x80, 0x0, 0x0, 0x7fff00000000, 0x5300dc, 0x157ce6, 0x1ae5abc1, 0x7fffcec10e48, 0x4cad9f, ...)
	/usr/local/go/src/runtime/sys_linux_amd64.s:587 +0x21
runtime.futexsleep(0x3285768, 0x0, 0xffffffffffffffff)
	/usr/local/go/src/runtime/os_linux.go:45 +0x46
runtime.notesleep(0x3285768)
	/usr/local/go/src/runtime/lock_futex.go:159 +0x9f
runtime.stopm()
	/usr/local/go/src/runtime/proc.go:1910 +0xc5
runtime.findrunnable(0xc000056800, 0x0)
	/usr/local/go/src/runtime/proc.go:2471 +0xa7f
runtime.schedule()
	/usr/local/go/src/runtime/proc.go:2669 +0x2d7
runtime.park_m(0xc000000f00)
	/usr/local/go/src/runtime/proc.go:2837 +0x9d
runtime.mcall(0x1c59250)
	/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc0008f08e0)
	/usr/local/go/src/runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc0008f08d8)
	/usr/local/go/src/sync/waitgroup.go:130 +0x65
golang.org/x/sync/errgroup.(*Group).Wait(0xc0008f08d0, 0xc0008d7920, 0x13)
	/go/pkg/mod/golang.org/x/sync@v0.0.0-20190911185100-cd5d95a43a6e/errgroup/errgroup.go:40 +0x31
github.com/gohugoio/hugo/commands.(*commandeer).fullBuild(0xc0004a2e00, 0x0, 0x0)
	/root/project/hugo/commands/hugo.go:328 +0x476
github.com/gohugoio/hugo/commands.(*commandeer).build(0xc0004a2e00, 0x0, 0x0)
	/root/project/hugo/commands/hugo.go:508 +0xaa
github.com/gohugoio/hugo/commands.(*commandsBuilder).newHugoCmd.func1(0xc000305080, 0xc000519c80, 0x0, 0x8, 0x0, 0x0)
	/root/project/hugo/commands/commands.go:171 +0x15d
github.com/spf13/cobra.(*Command).execute(0xc000305080, 0xc000128010, 0x8, 0x8, 0xc000305080, 0xc000128010)
	/go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:850 +0x47c
github.com/spf13/cobra.(*Command).ExecuteC(0xc000305080, 0xc0005304d0, 0x8, 0xc000519680)
	/go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:958 +0x375
github.com/gohugoio/hugo/commands.Execute(0xc000128010, 0x8, 0x8, 0x4c4f45, 0xc00010e058, 0x0, 0x0)
	/root/project/hugo/commands/hugo.go:90 +0xb9
main.main()
	/root/project/hugo/main.go:23 +0x76

goroutine 7 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000feff0)
	/go/pkg/mod/go.opencensus.io@v0.22.0/stats/view/worker.go:154 +0x105
created by go.opencensus.io/stats/view.init.0
	/go/pkg/mod/go.opencensus.io@v0.22.0/stats/view/worker.go:32 +0x57

goroutine 76 [syscall]:
syscall.Syscall6(0x101, 0xffffffffffffff9c, 0xc001713b80, 0x80000, 0x0, 0x0, 0x0, 0x4fff1c, 0xc000001980, 0x300000002)
	/usr/local/go/src/syscall/asm_linux_amd64.s:41 +0x5
syscall.openat(0xffffffffffffff9c, 0xc0008d15e0, 0x1c, 0x80000, 0xc000000000, 0x529425, 0xc000001980, 0x200000003)
	/usr/local/go/src/syscall/zsyscall_linux_amd64.go:68 +0xbd
syscall.Open(...)
	/usr/local/go/src/syscall/syscall_linux.go:152
os.openFileNolog(0xc0008d15e0, 0x1c, 0x0, 0xc000000000, 0x7f247915ad08, 0x26, 0x0)
	/usr/local/go/src/os/file_unix.go:200 +0x8f
os.OpenFile(0xc0008d15e0, 0x1c, 0x0, 0x0, 0xc000001980, 0x300000002, 0xc000001980)
	/usr/local/go/src/os/file.go:327 +0x65
os.Open(...)
	/usr/local/go/src/os/file.go:307
github.com/spf13/afero.OsFs.Open(0xc0008d15e0, 0x1c, 0xc000001980, 0xc000054000, 0xc00375baf8, 0x4d8a65)
	/go/pkg/mod/github.com/spf13/afero@v1.4.1/os.go:55 +0x4a
github.com/gohugoio/hugo/hugofs.(*baseFileDecoratorFs).open(0xc000385d60, 0xc0008d15e0, 0x1c, 0x562505, 0xc00276ede0, 0x1e5dd80, 0xc000a33c10)
	/root/project/hugo/hugofs/decorators.go:194 +0x4b
github.com/gohugoio/hugo/hugofs.NewBaseFileDecorator.func1.2(0x20f3dc0, 0xc000a22960, 0x21488ba, 0x6)
	/root/project/hugo/hugofs/decorators.go:121 +0x3f
github.com/gohugoio/hugo/hugofs.FileMeta.Open(0xc000a22960, 0x0, 0x0, 0xe3a1d0, 0x0)
	/root/project/hugo/hugofs/fileinfo.go:188 +0x78
github.com/gohugoio/hugo/hugolib.(*pageMap).newResource.func1(0x0, 0x0, 0xc00375bb98, 0xa4ae3c)
	/root/project/hugo/hugolib/content_map_page.go:250 +0x2a
github.com/gohugoio/hugo/resources.(*resourceFileInfo).ReadSeekCloser(0xc000147dc0, 0x0, 0x0, 0xc0028945c0, 0xc0028a4000)
	/root/project/hugo/resources/resource.go:594 +0xd0
github.com/gohugoio/hugo/resources.(*genericResource).Publish.func1()
	/root/project/hugo/resources/resource.go:265 +0x69
sync.(*Once).doSlow(0xc000f2067c, 0xc00375bcd8)
	/usr/local/go/src/sync/once.go:66 +0xec
sync.(*Once).Do(...)
	/usr/local/go/src/sync/once.go:57
github.com/gohugoio/hugo/resources.(*genericResource).Publish(0xc000ce3790, 0x0, 0x7f24792e5028)
	/root/project/hugo/resources/resource.go:263 +0x9b
github.com/gohugoio/hugo/resources.(*resourceAdapter).Publish(0xc0006b6ab0, 0x2647ec0, 0xc0006b6ab0)
	/root/project/hugo/resources/transform.go:218 +0x4e
github.com/gohugoio/hugo/hugolib.(*pageState).renderResources.func1()
	/root/project/hugo/hugolib/page.go:532 +0x37e
sync.(*Once).doSlow(0xc000a1ae8c, 0xc00375be78)
	/usr/local/go/src/sync/once.go:66 +0xec
sync.(*Once).Do(...)
	/usr/local/go/src/sync/once.go:57
github.com/gohugoio/hugo/hugolib.(*pageState).renderResources(0xc000da1a70, 0x0, 0x0)
	/root/project/hugo/hugolib/page.go:515 +0x89
github.com/gohugoio/hugo/hugolib.pageRenderer(0xc0016da800, 0xc0007fd680, 0xc0017ea000, 0xc00179efc0, 0xc0017c0ed0)
	/root/project/hugo/hugolib/site_render.go:115 +0x4dc
created by github.com/gohugoio/hugo/hugolib.(*Site).renderPages
	/root/project/hugo/hugolib/site_render.go:74 +0x165

goroutine 72 [chan receive]:
github.com/gohugoio/hugo/hugolib.(*Site).errorCollator(0xc0007fd680, 0xc00179efc0, 0xc00179f020)
	/root/project/hugo/hugolib/site.go:1593 +0x72
created by github.com/gohugoio/hugo/hugolib.(*Site).renderPages
	/root/project/hugo/hugolib/site_render.go:68 +0xdb

goroutine 69 [chan receive]:
github.com/gohugoio/hugo/hugolib.(*HugoSites).Build.func1(0xc000236300, 0xc0008dfb60, 0xc00010f380)
	/root/project/hugo/hugolib/hugo_sites_build.go:63 +0x7d
created by github.com/gohugoio/hugo/hugolib.(*HugoSites).Build
	/root/project/hugo/hugolib/hugo_sites_build.go:60 +0x226

goroutine 68 [semacquire]:
sync.runtime_Semacquire(0xc0017c0ed8)
	/usr/local/go/src/runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc0017c0ed0)
	/usr/local/go/src/sync/waitgroup.go:130 +0x65
github.com/gohugoio/hugo/hugolib.(*Site).renderPages(0xc0007fd680, 0xc0016da800, 0x0, 0xc0016f5a00)
	/root/project/hugo/hugolib/site_render.go:93 +0x225
github.com/gohugoio/hugo/hugolib.(*Site).render(0xc0007fd680, 0xc0016da800, 0x0, 0x0)
	/root/project/hugo/hugolib/site.go:1234 +0x59
github.com/gohugoio/hugo/hugolib.(*HugoSites).render(0xc000236300, 0xc0008e3100, 0x32c9250, 0x1)
	/root/project/hugo/hugolib/hugo_sites_build.go:322 +0x435
github.com/gohugoio/hugo/hugolib.(*HugoSites).Build.func4()
	/root/project/hugo/hugolib/hugo_sites_build.go:147 +0x3c
runtime/trace.WithRegion(0x2634920, 0xc0008f0900, 0x2148d10, 0x6, 0xc001107e60)
	/usr/local/go/src/runtime/trace/annotation.go:137 +0xf8
github.com/gohugoio/hugo/hugolib.(*HugoSites).Build(0xc000236300, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/root/project/hugo/hugolib/hugo_sites_build.go:149 +0x7d9
github.com/gohugoio/hugo/commands.(*commandeer).buildSites(...)
	/root/project/hugo/commands/hugo.go:737
github.com/gohugoio/hugo/commands.(*commandeer).fullBuild.func3(0xc0005f6958, 0x0)
	/root/project/hugo/commands/hugo.go:310 +0x7c
golang.org/x/sync/errgroup.(*Group).Go.func1(0xc0008f08d0, 0xc0008d7920)
	/go/pkg/mod/golang.org/x/sync@v0.0.0-20190911185100-cd5d95a43a6e/errgroup/errgroup.go:57 +0x59
created by golang.org/x/sync/errgroup.(*Group).Go
	/go/pkg/mod/golang.org/x/sync@v0.0.0-20190911185100-cd5d95a43a6e/errgroup/errgroup.go:54 +0x66

rax    0xca
rbx    0x3285620
rcx    0x530503
rdx    0x0
rdi    0x3285768
rsi    0x80
rbp    0x7fffcec10e10
rsp    0x7fffcec10dc8
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x3
r13    0x3284980
r14    0xffffffffffff
r15    0x1
rip    0x530501
rflags 0x286
cs     0x33
fs     0x0
gs     0x0
8

Do the stack trace look similar when you repeat this?

9

Yes, it does. Various goroutines waiting on semaphores, selecting or receiving on a channel, plus one routine that’s sitting inside what looks like an open syscall.

10

Ahah! Thank you so much for the help, and I’ve finally figured out what is going on. The content directory had some special files (named pipes) generated as part of the non-doc build, and it looks like hugo was trying to read them. As you’d expect, it ended up just sitting and waiting forever!

I figured this out by running under strace and sending a SIGABRT to the process. One of the threads then shows something like

[pid 2543583] 13:29:26 <... openat resumed>) = ?

and then you can search backwards through the log to see what that PID was doing. Phew!

I wonder whether hugo should have some logic to make sure that it doesn’t try to read files other than regular ones?

11

Can you post some more info about what exactly created those pipes and how they looked like so we can get back to this if a comparable issue comes up? I am working under Unix systems and did not come across this file type (my guess is the filename made Hugo think it’s a “stream”).

12

This topic was automatically closed 2 days after the last reply. New replies are no longer allowed.