How can I diagnose a "hanging hugo"?

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

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.

I use

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

to get the information

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

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.

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.

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

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

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
	/usr/local/go/src/runtime/lock_futex.go:159 +0x9f
	/usr/local/go/src/runtime/proc.go:1910 +0xc5
runtime.findrunnable(0xc000056800, 0x0)
	/usr/local/go/src/runtime/proc.go:2471 +0xa7f
	/usr/local/go/src/runtime/proc.go:2669 +0x2d7
	/usr/local/go/src/runtime/proc.go:2837 +0x9d
	/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b

goroutine 1 [semacquire]:
	/usr/local/go/src/runtime/sema.go:56 +0x45
	/usr/local/go/src/sync/waitgroup.go:130 +0x65*Group).Wait(0xc0008f08d0, 0xc0008d7920, 0x13)
	/go/pkg/mod/ +0x31*commandeer).fullBuild(0xc0004a2e00, 0x0, 0x0)
	/root/project/hugo/commands/hugo.go:328 +0x476*commandeer).build(0xc0004a2e00, 0x0, 0x0)
	/root/project/hugo/commands/hugo.go:508 +0xaa*commandsBuilder).newHugoCmd.func1(0xc000305080, 0xc000519c80, 0x0, 0x8, 0x0, 0x0)
	/root/project/hugo/commands/commands.go:171 +0x15d*Command).execute(0xc000305080, 0xc000128010, 0x8, 0x8, 0xc000305080, 0xc000128010)
	/go/pkg/mod/ +0x47c*Command).ExecuteC(0xc000305080, 0xc0005304d0, 0x8, 0xc000519680)
	/go/pkg/mod/ +0x375, 0x8, 0x8, 0x4c4f45, 0xc00010e058, 0x0, 0x0)
	/root/project/hugo/commands/hugo.go:90 +0xb9
	/root/project/hugo/main.go:23 +0x76

goroutine 7 [select]:*worker).start(0xc0000feff0)
	/go/pkg/mod/ +0x105
created by
	/go/pkg/mod/ +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
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
	/usr/local/go/src/os/file.go:307, 0x1c, 0xc000001980, 0xc000054000, 0xc00375baf8, 0x4d8a65)
	/go/pkg/mod/ +0x4a*baseFileDecoratorFs).open(0xc000385d60, 0xc0008d15e0, 0x1c, 0x562505, 0xc00276ede0, 0x1e5dd80, 0xc000a33c10)
	/root/project/hugo/hugofs/decorators.go:194 +0x4b, 0xc000a22960, 0x21488ba, 0x6)
	/root/project/hugo/hugofs/decorators.go:121 +0x3f, 0x0, 0x0, 0xe3a1d0, 0x0)
	/root/project/hugo/hugofs/fileinfo.go:188 +0x78*pageMap).newResource.func1(0x0, 0x0, 0xc00375bb98, 0xa4ae3c)
	/root/project/hugo/hugolib/content_map_page.go:250 +0x2a*resourceFileInfo).ReadSeekCloser(0xc000147dc0, 0x0, 0x0, 0xc0028945c0, 0xc0028a4000)
	/root/project/hugo/resources/resource.go:594 +0xd0*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
	/usr/local/go/src/sync/once.go:57*genericResource).Publish(0xc000ce3790, 0x0, 0x7f24792e5028)
	/root/project/hugo/resources/resource.go:263 +0x9b*resourceAdapter).Publish(0xc0006b6ab0, 0x2647ec0, 0xc0006b6ab0)
	/root/project/hugo/resources/transform.go:218 +0x4e*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
	/usr/local/go/src/sync/once.go:57*pageState).renderResources(0xc000da1a70, 0x0, 0x0)
	/root/project/hugo/hugolib/page.go:515 +0x89, 0xc0007fd680, 0xc0017ea000, 0xc00179efc0, 0xc0017c0ed0)
	/root/project/hugo/hugolib/site_render.go:115 +0x4dc
created by*Site).renderPages
	/root/project/hugo/hugolib/site_render.go:74 +0x165

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

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

goroutine 68 [semacquire]:
	/usr/local/go/src/runtime/sema.go:56 +0x45
	/usr/local/go/src/sync/waitgroup.go:130 +0x65*Site).renderPages(0xc0007fd680, 0xc0016da800, 0x0, 0xc0016f5a00)
	/root/project/hugo/hugolib/site_render.go:93 +0x225*Site).render(0xc0007fd680, 0xc0016da800, 0x0, 0x0)
	/root/project/hugo/hugolib/site.go:1234 +0x59*HugoSites).render(0xc000236300, 0xc0008e3100, 0x32c9250, 0x1)
	/root/project/hugo/hugolib/hugo_sites_build.go:322 +0x435*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*HugoSites).Build(0xc000236300, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/root/project/hugo/hugolib/hugo_sites_build.go:149 +0x7d9*commandeer).buildSites(...)
	/root/project/hugo/commands/hugo.go:737*commandeer).fullBuild.func3(0xc0005f6958, 0x0)
	/root/project/hugo/commands/hugo.go:310 +0x7c*Group).Go.func1(0xc0008f08d0, 0xc0008d7920)
	/go/pkg/mod/ +0x59
created by*Group).Go
	/go/pkg/mod/ +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

Do the stack trace look similar when you repeat this?

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.

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?

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”).

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