search

wkhtmltopdf / wkhtmltopdf

Convert HTML to PDF using Webkit (QtWebKit)
https://wkhtmltopdf.org
GNU Lesser General Public License v3.0
13.91k stars 1.8k forks source link

wkhtmltopdf hangs on network errors #2254

Open AnthonyAkentiev opened 9 years ago

AnthonyAkentiev commented 9 years ago

Version: 0.12.2.1 (with patched qt), same with 0.12.1 OS: Ubuntu 3.13.0-44-generic #73-Ubuntu SMP Tue Dec 16 00:22:43 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

screen shot 2015-03-22 at 15 34 39

1) OS is a completely clean new "install". 2) sudo apt-get install gdebi 3) sudo gdebi wkhtmltox-0.12.2.1_linux-jessie-amd64-2.deb 4) Then i just

wkhtmltopdf "http://lenta.ru" lenta.pdf

lenta.ru is a news web site, so the content is updated frequently. So to be sure contents is

not changed - you can check my web page -

wkhtmltopdf "http://www.adaperio.ru/engine.html#/search/%D0%BD030%D1%80%D0%BD98" sample.pdf

Output:

Unable to load library icui18n "Cannot load library icui18n: (icui18n: cannot open shared object file: No such file or directory)" Loading pages (1/6) Fontconfig warning: ignoring UTF-8: not a valid region tag ] 50% [======================================================> ] 90%

And it freezes (for 2-5 hours easily). Sometimes it is OK and process finishes normally with good PDF file. Please run several times.

The end of "strace -f -e trace=network -s 10000 wkhtmltopdf "http://lenta.ru" lenta.pdf" output is: [pid 1301] setsockopt(29, SOL_SOCKET, SO_OOBINLINE, [1], 4) = 0 [pid 1301] connect(29, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("54.243.146.98")}, 16) = -1 EINPROGRESS (Operation now in progress) [pid 1301] connect(29, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("54.243.146.98")}, 16) = 0 [pid 1301] getsockname(29, {sa_family=AF_INET, sin_port=htons(59900), sin_addr=inet_addr("172.31.5.30")}, [16]) = 0 [pid 1301] getpeername(29, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("54.243.146.98")}, [16]) = 0 [pid 1301] getsockopt(29, SOL_SOCKET, SO_TYPE, [1], [4]) = 0 [pid 1301] setsockopt(29, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 ...and then freezes...

On my MAC OS X the same worked fine 10/10 times. Output: "Loading pages (1/6) Counting pages (2/6)
Resolving links (4/6)
Loading headers and footers (5/6)
Printing pages (6/6) Done
Exit with code 1 due to network error: HostNotFoundError" (but its ok and PDF is generated)

Please help. Thank you!

AnthonyAkentiev commented 9 years ago

Same issue on clean Windows Server 2012!

wkhtmltopdf.exe "http://www.adaperio.ru/engine.html#/search/%D0%BD030%D1%80%D0%BD98" sample.pdf

AnthonyAkentiev commented 9 years ago

Same behaviour with "http://yandex.ru"

DanielCeregatti commented 9 years ago

I'm experiencing what seems to be a similar issue, although it's very random here. I'm on a fully updated 64 bit Debian 7 using 64 bit wkhtmltopdf 0.12.2.1 from wkhtmltopdf.org. Here's a sample command line:

wkhtmltopdf --enable-javascript --debug-javascript --cookie SESSIONID 94F2B96E6BBE3095E41A038014882342 --window-status waitEvent --orientation Portrait "http://theUrl/theArgs" test.pdf

In many cases wkhtmltopdf simply hangs. Requests stop showing up in the apache access log, and output from wkhtmltopdf just stops. There is no other output indicating why it's stopped.

I've used lsof -n | grep wkhtmltopdf to see if wkhtmltopdf has any open TCP connections at the time of the hang and none show up. I've used strace as well, but I'm still interpreting those results.

As a test, I've loaded the URL in Chrome. I've conducted this test several times, and without exception, the page always loads and window.status is set properly when javascript finishes executing.

Using lsof and strace just isn't going to cut it to debug this. Is there any way for wkhtmltopdf to output more debug/progress info? The equivalent of what is output to Chrome's network tab in the developer console would be great, as there are times in the strace output that it looks like this might even be a DNS lookup that's hanging things up.

Daniel

DanielCeregatti commented 9 years ago

I've been investigating this problem. I've built a debug build of wkhtmltopdf and kept running it until I encountered the hang. It doesn't take too many tries to replicate this problem. Once I triggered the hang, I attached gdb. Here's the backtrace:

(gdb) bt
#0  0x00007fc2433cb453 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x0000000002093939 in qt_safe_select (nfds=5, fdread=0x4408978, fdwrite=0x4408c10, fdexcept=0x4408ea8, orig_timeout=0x7fff94c8bc50)
    at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qcore_unix.cpp:89
#2  0x0000000002095b50 in QEventDispatcherUNIX::select (this=0x43fa290, nfds=5, readfds=0x4408978, writefds=0x4408c10, exceptfds=0x4408ea8, timeout=0x7fff94c8bc50)
    at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qeventdispatcher_unix.cpp:649
#3  0x00000000020945cd in QEventDispatcherUNIXPrivate::doSelect (this=0x44087c0, flags=..., timeout=0x7fff94c8bc50)
    at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qeventdispatcher_unix.cpp:223
#4  0x0000000002096b25 in QEventDispatcherUNIX::processEvents (this=0x43fa290, flags=...) at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qeventdispatcher_unix.cpp:936
#5  0x0000000002064308 in QCoreApplication::processEvents (flags=...) at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qcoreapplication.cpp:1140
#6  0x000000000042a53a in wkhtmltopdf::ConverterPrivate::convert (this=0x440ad30) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:94
#7  0x000000000042a781 in wkhtmltopdf::Converter::convert (this=0x7fff94c932d0) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:149
#8  0x00000000004510d2 in main (argc=12, argv=0x7fff94c93458) at /home/daniel/wkhtmltopdf/src/pdf/wkhtmltopdf.cc:187

The problem seems to be in /home/daniel/wkhtmltopdf/src/lib/converter.cc:93

while (!convertionDone) {
  qApp->processEvents(QEventLoop::WaitForMoreEvents | QEventLoop::AllEvents);

This becomes an infinite loop. To test this, I set a breakpoint just after the loop:

(gdb) b /home/daniel/wkhtmltopdf/src/lib/converter.cc:95
Breakpoint 2 at 0x42a549: file /home/daniel/wkhtmltopdf/src/lib/converter.cc, line 95.
(gdb) c
Continuing.

The breakpoint is never reached.

I've forked this project and will now look at adding some debug output in that event loop in the hopes that it will report something relevant when it gets stuck there. I'll report again once I know more.

Daniel

AnthonyAkentiev commented 9 years ago

@DanielCeregatti - Very cool! I hope that you will find the problem soon!

ashkulz commented 9 years ago

@DanielCeregatti: can you try and see if bgra/wkhtmltopdf@91329c452208f14536a0ade4fa0db86b7a1da210 fixes things for you? I never got feedback on it and it seems you can reproduce the issue.

ashkulz commented 9 years ago

@DanielCeregatti: can you try the fix-hangs branch and see if it works for you?

DanielCeregatti commented 9 years ago

So far so good. I've yet to see it hang when using this branch. I plan to deploying a build of this branch to my production environment soon and I'm hopeful that the problem will no longer manifest itself. Thanks for the quick fix!

DanielCeregatti commented 9 years ago

I guess I spoke too soon. I really hadn't done any true stress testing and decided I'd run wkhtmltopdf in a shell loop and let it run overnight to be completely sure. I barely made it to iteration number 20 before it hung again:

(gdb) bt
#0  0x00007fd66e38d453 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x0000000002093939 in qt_safe_select (nfds=5, fdread=0x3a078f8, fdwrite=0x3a07b90, fdexcept=0x3a07e28, orig_timeout=0x7fff7b926a40) at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qcore_unix.cpp:89
#2  0x0000000002095b50 in QEventDispatcherUNIX::select (this=0x39f9290, nfds=5, readfds=0x3a078f8, writefds=0x3a07b90, exceptfds=0x3a07e28, timeout=0x7fff7b926a40)
    at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qeventdispatcher_unix.cpp:649
#3  0x00000000020945cd in QEventDispatcherUNIXPrivate::doSelect (this=0x3a07740, flags=..., timeout=0x7fff7b926a40) at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qeventdispatcher_unix.cpp:223
#4  0x0000000002096b25 in QEventDispatcherUNIX::processEvents (this=0x39f9290, flags=...) at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qeventdispatcher_unix.cpp:936
#5  0x0000000002064308 in QCoreApplication::processEvents (flags=...) at /home/daniel/wkhtmltopdf/qt/src/corelib/kernel/qcoreapplication.cpp:1140
#6  0x000000000042a530 in wkhtmltopdf::ConverterPrivate::convert (this=0x3a0a100) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:94
#7  0x000000000042a77d in wkhtmltopdf::Converter::convert (this=0x7fff7b92e0c0) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:151
#8  0x0000000000451072 in main (argc=12, argv=0x7fff7b92e248) at /home/daniel/wkhtmltopdf/src/pdf/wkhtmltopdf.cc:187
(gdb) f 6
#6  0x000000000042a530 in wkhtmltopdf::ConverterPrivate::convert (this=0x3a0a100) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:94
warning: Source file is more recent than executable.
94                      QCoreApplication::processEvents();
(gdb) l
89
90      bool ConverterPrivate::convert() {
91              convertionDone=false;
92              beginConvert();
93              while (!convertionDone) {
94                      QCoreApplication::processEvents();
95                      QCoreApplication::sendPostedEvents();
96              }
97              return !error;
98      }
(gdb) b /home/daniel/wkhtmltopdf/src/lib/converter.cc:97
Breakpoint 1 at 0x42a544: file /home/daniel/wkhtmltopdf/src/lib/converter.cc, line 97.
(gdb) c
Continuing.

I let it run for another 10 minutes. The breakpoint is never reached.

Regarding this:

warning: Source file is more recent than executable.

I have a clone of the repo on the machine I use for testing and have it switched to the fix-hang branch but I build on another machine. We're still running Wheezy, and I spun up a Jessie instance just to run the build. I then install the .deb file from the build on the test machine.

I must confess, I haven't used gdb or coded in C/C++ in years, and I'm quite rusty. Is there anything you can suggest for figuring out what is causing this?

DanielCeregatti commented 9 years ago

Here's some more information when wkhtmltopdf hangs:

$ lsof -n | grep 10551
COMMAND     PID   TID       USER   FD      TYPE  DEVICE  SIZE/OFF    NODE NAME
wkhtmltop 10551           daniel  cwd       DIR             254,33      4096     131073 /home/daniel
wkhtmltop 10551           daniel  rtd       DIR              254,1      4096          2 /
wkhtmltop 10551           daniel  txt       REG              254,1 206123457      13977 /usr/local/bin/wkhtmltopdf
wkhtmltop 10551           daniel  mem       REG              254,1     22928     525115 /lib/x86_64-linux-gnu/libnss_dns-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     47616     525095 /lib/x86_64-linux-gnu/libnss_files-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     80712     525117 /lib/x86_64-linux-gnu/libresolv-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1   2048512     524707 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0
wkhtmltop 10551           daniel  mem       REG              254,1    392072     529331 /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0
wkhtmltop 10551           daniel  mem       REG              254,1     14392     527992 /usr/lib/x86_64-linux-gnu/gconv/UTF-16.so
wkhtmltop 10551           daniel  mem       REG              254,1     20648     529691 /usr/lib/x86_64-linux-gnu/libXdmcp.so.6.0.0
wkhtmltop 10551           daniel  mem       REG              254,1     10896     530228 /usr/lib/x86_64-linux-gnu/libXau.so.6.0.0
wkhtmltop 10551           daniel  mem       REG              254,1    129840     530395 /usr/lib/x86_64-linux-gnu/libxcb.so.1.1.0
wkhtmltop 10551           daniel  mem       REG              254,1    169992     524349 /lib/x86_64-linux-gnu/libexpat.so.1.6.0
wkhtmltop 10551           daniel  mem       REG              254,1   1599504     525100 /lib/x86_64-linux-gnu/libc-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     89056     524448 /lib/x86_64-linux-gnu/libgcc_s.so.1
wkhtmltop 10551           daniel  mem       REG              254,1    530736     525093 /lib/x86_64-linux-gnu/libm-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1    991600     529428 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.17
wkhtmltop 10551           daniel  mem       REG              254,1    131107     525119 /lib/x86_64-linux-gnu/libpthread-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     31744     525118 /lib/x86_64-linux-gnu/librt-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     14768     525110 /lib/x86_64-linux-gnu/libdl-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     92752     524421 /lib/x86_64-linux-gnu/libz.so.1.2.7
wkhtmltop 10551           daniel  mem       REG              254,1   1289744     528981 /usr/lib/x86_64-linux-gnu/libX11.so.6.3.0
wkhtmltop 10551           daniel  mem       REG              254,1     74408     529698 /usr/lib/x86_64-linux-gnu/libXext.so.6.4.0
wkhtmltop 10551           daniel  mem       REG              254,1    650808     528743 /usr/lib/x86_64-linux-gnu/libfreetype.so.6.8.1
wkhtmltop 10551           daniel  mem       REG              254,1    225128     530292 /usr/lib/x86_64-linux-gnu/libfontconfig.so.1.5.0
wkhtmltop 10551           daniel  mem       REG              254,1     38768     528479 /usr/lib/x86_64-linux-gnu/libXrender.so.1.3.0
wkhtmltop 10551           daniel  mem       REG              254,1    158640     524445 /lib/x86_64-linux-gnu/libpng12.so.0.49.0
wkhtmltop 10551           daniel  mem       REG              254,1    238848     524304 /usr/lib/x86_64-linux-gnu/libjpeg.so.8.4.0
wkhtmltop 10551           daniel  mem       REG              254,1    136936     525116 /lib/x86_64-linux-gnu/ld-2.13.so
wkhtmltop 10551           daniel  mem       REG              254,1     34128       6013 /var/cache/fontconfig/945677eb7aeaf62f1d50efc3fb3ec7d8-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1     35304       6008 /var/cache/fontconfig/6d41288fd70b0be22e8c3a91e032eec0-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1     10624       6018 /var/cache/fontconfig/de9486f0b47a4d768a594cb4198cb1c6-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1     28448       5999 /var/cache/fontconfig/3f7329c5293ffd510edef78f73874cfd-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1     13288       6016 /var/cache/fontconfig/6386b86020ecc1ef9690bb720a13964f-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1      5536       5995 /var/cache/fontconfig/099525ddca5eae4f2477b69cf2d7f16d-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1      5544       5998 /var/cache/fontconfig/61092ac79d9058a69eda095afa0a78f1-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1      5856       5997 /var/cache/fontconfig/a722efc6911bbe16667b1a77497ffd37-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1      5776       5996 /var/cache/fontconfig/d63fdd8e0f42559533dd777c334fdfcc-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1     33848      14694 /var/cache/fontconfig/e13b20fdb08344e0e664864cc2ede53d-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1    115808       6014 /var/cache/fontconfig/44f970ff9b6a3db194ffc7bb3ea380d6-le64.cache-3
wkhtmltop 10551           daniel  mem       REG              254,1   1534672     524749 /usr/lib/locale/locale-archive
wkhtmltop 10551           daniel  mem       REG              254,1     26066     525139 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
wkhtmltop 10551           daniel    0u      CHR              136,5       0t0          8 /dev/pts/5
wkhtmltop 10551           daniel    1u      CHR              136,5       0t0          8 /dev/pts/5
wkhtmltop 10551           daniel    2u      CHR              136,5       0t0          8 /dev/pts/5
wkhtmltop 10551           daniel    3r      DIR              254,1     20480     278953 /usr/share/bash-completion/completions
wkhtmltop 10551           daniel    4r     FIFO                0,8       0t0    5411455 pipe
wkhtmltop 10551           daniel    5w     FIFO                0,8       0t0    5411455 pipe
wkhtmltop 10551           daniel    6r     FIFO                0,8       0t0    5411458 pipe
wkhtmltop 10551           daniel    7w     FIFO                0,8       0t0    5411458 pipe
wkhtmltop 10551           daniel    8r     FIFO                0,8       0t0    5410750 pipe
wkhtmltop 10551           daniel    9w     FIFO                0,8       0t0    5410750 pipe
wkhtmltop 10551           daniel   10r     FIFO                0,8       0t0    5410751 pipe
wkhtmltop 10551           daniel   11w     FIFO                0,8       0t0    5410751 pipe
wkhtmltop 10551 10552     daniel  cwd       DIR             254,33      4096     131073 /home/daniel
wkhtmltop 10551 10552     daniel  rtd       DIR              254,1      4096          2 /
wkhtmltop 10551 10552     daniel  txt       REG              254,1 206123457      13977 /usr/local/bin/wkhtmltopdf
wkhtmltop 10551 10552     daniel  mem       REG              254,1     22928     525115 /lib/x86_64-linux-gnu/libnss_dns-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     47616     525095 /lib/x86_64-linux-gnu/libnss_files-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     47616     525095 /lib/x86_64-linux-gnu/libnss_files-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     80712     525117 /lib/x86_64-linux-gnu/libresolv-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1   2048512     524707 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    392072     529331 /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1     14392     527992 /usr/lib/x86_64-linux-gnu/gconv/UTF-16.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     20648     529691 /usr/lib/x86_64-linux-gnu/libXdmcp.so.6.0.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1     10896     530228 /usr/lib/x86_64-linux-gnu/libXau.so.6.0.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    129840     530395 /usr/lib/x86_64-linux-gnu/libxcb.so.1.1.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    169992     524349 /lib/x86_64-linux-gnu/libexpat.so.1.6.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1   1599504     525100 /lib/x86_64-linux-gnu/libc-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     89056     524448 /lib/x86_64-linux-gnu/libgcc_s.so.1
wkhtmltop 10551 10552     daniel  mem       REG              254,1    530736     525093 /lib/x86_64-linux-gnu/libm-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1    991600     529428 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.17
wkhtmltop 10551 10552     daniel  mem       REG              254,1    131107     525119 /lib/x86_64-linux-gnu/libpthread-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     31744     525118 /lib/x86_64-linux-gnu/librt-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     14768     525110 /lib/x86_64-linux-gnu/libdl-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     92752     524421 /lib/x86_64-linux-gnu/libz.so.1.2.7
wkhtmltop 10551 10552     daniel  mem       REG              254,1   1289744     528981 /usr/lib/x86_64-linux-gnu/libX11.so.6.3.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1     74408     529698 /usr/lib/x86_64-linux-gnu/libXext.so.6.4.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    650808     528743 /usr/lib/x86_64-linux-gnu/libfreetype.so.6.8.1
wkhtmltop 10551 10552     daniel  mem       REG              254,1    225128     530292 /usr/lib/x86_64-linux-gnu/libfontconfig.so.1.5.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1     38768     528479 /usr/lib/x86_64-linux-gnu/libXrender.so.1.3.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    158640     524445 /lib/x86_64-linux-gnu/libpng12.so.0.49.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    238848     524304 /usr/lib/x86_64-linux-gnu/libjpeg.so.8.4.0
wkhtmltop 10551 10552     daniel  mem       REG              254,1    136936     525116 /lib/x86_64-linux-gnu/ld-2.13.so
wkhtmltop 10551 10552     daniel  mem       REG              254,1     34128       6013 /var/cache/fontconfig/945677eb7aeaf62f1d50efc3fb3ec7d8-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1     35304       6008 /var/cache/fontconfig/6d41288fd70b0be22e8c3a91e032eec0-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1     10624       6018 /var/cache/fontconfig/de9486f0b47a4d768a594cb4198cb1c6-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1     28448       5999 /var/cache/fontconfig/3f7329c5293ffd510edef78f73874cfd-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1     13288       6016 /var/cache/fontconfig/6386b86020ecc1ef9690bb720a13964f-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1      5536       5995 /var/cache/fontconfig/099525ddca5eae4f2477b69cf2d7f16d-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1      5544       5998 /var/cache/fontconfig/61092ac79d9058a69eda095afa0a78f1-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1      5856       5997 /var/cache/fontconfig/a722efc6911bbe16667b1a77497ffd37-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1      5776       5996 /var/cache/fontconfig/d63fdd8e0f42559533dd777c334fdfcc-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1     33848      14694 /var/cache/fontconfig/e13b20fdb08344e0e664864cc2ede53d-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1    115808       6014 /var/cache/fontconfig/44f970ff9b6a3db194ffc7bb3ea380d6-le64.cache-3
wkhtmltop 10551 10552     daniel  mem       REG              254,1   1534672     524749 /usr/lib/locale/locale-archive
wkhtmltop 10551 10552     daniel  mem       REG              254,1     26066     525139 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
wkhtmltop 10551 10552     daniel    0u      CHR              136,5       0t0          8 /dev/pts/5
wkhtmltop 10551 10552     daniel    1u      CHR              136,5       0t0          8 /dev/pts/5
wkhtmltop 10551 10552     daniel    2u      CHR              136,5       0t0          8 /dev/pts/5
wkhtmltop 10551 10552     daniel    3r      DIR              254,1     20480     278953 /usr/share/bash-completion/completions
wkhtmltop 10551 10552     daniel    4r     FIFO                0,8       0t0    5411455 pipe
wkhtmltop 10551 10552     daniel    5w     FIFO                0,8       0t0    5411455 pipe
wkhtmltop 10551 10552     daniel    6r     FIFO                0,8       0t0    5411458 pipe
wkhtmltop 10551 10552     daniel    7w     FIFO                0,8       0t0    5411458 pipe
wkhtmltop 10551 10552     daniel    8r     FIFO                0,8       0t0    5410750 pipe
wkhtmltop 10551 10552     daniel    9w     FIFO                0,8       0t0    5410750 pipe
wkhtmltop 10551 10552     daniel   10r     FIFO                0,8       0t0    5410751 pipe
wkhtmltop 10551 10552     daniel   11w     FIFO                0,8       0t0    5410751 pipe
QThread   10551 10553     daniel  cwd       DIR             254,33      4096     131073 /home/daniel
QThread   10551 10553     daniel  rtd       DIR              254,1      4096          2 /
QThread   10551 10553     daniel  txt       REG              254,1 206123457      13977 /usr/local/bin/wkhtmltopdf
QThread   10551 10553     daniel  mem       REG              254,1     22928     525115 /lib/x86_64-linux-gnu/libnss_dns-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     47616     525095 /lib/x86_64-linux-gnu/libnss_files-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     80712     525117 /lib/x86_64-linux-gnu/libresolv-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1   2048512     524707 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0
QThread   10551 10553     daniel  mem       REG              254,1    392072     529331 /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0
QThread   10551 10553     daniel  mem       REG              254,1     14392     527992 /usr/lib/x86_64-linux-gnu/gconv/UTF-16.so
QThread   10551 10553     daniel  mem       REG              254,1     20648     529691 /usr/lib/x86_64-linux-gnu/libXdmcp.so.6.0.0
QThread   10551 10553     daniel  mem       REG              254,1     10896     530228 /usr/lib/x86_64-linux-gnu/libXau.so.6.0.0
QThread   10551 10553     daniel  mem       REG              254,1    129840     530395 /usr/lib/x86_64-linux-gnu/libxcb.so.1.1.0
QThread   10551 10553     daniel  mem       REG              254,1    169992     524349 /lib/x86_64-linux-gnu/libexpat.so.1.6.0
QThread   10551 10553     daniel  mem       REG              254,1   1599504     525100 /lib/x86_64-linux-gnu/libc-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     89056     524448 /lib/x86_64-linux-gnu/libgcc_s.so.1
QThread   10551 10553     daniel  mem       REG              254,1    530736     525093 /lib/x86_64-linux-gnu/libm-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1    991600     529428 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.17
QThread   10551 10553     daniel  mem       REG              254,1    131107     525119 /lib/x86_64-linux-gnu/libpthread-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     31744     525118 /lib/x86_64-linux-gnu/librt-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     14768     525110 /lib/x86_64-linux-gnu/libdl-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     92752     524421 /lib/x86_64-linux-gnu/libz.so.1.2.7
QThread   10551 10553     daniel  mem       REG              254,1   1289744     528981 /usr/lib/x86_64-linux-gnu/libX11.so.6.3.0
QThread   10551 10553     daniel  mem       REG              254,1     74408     529698 /usr/lib/x86_64-linux-gnu/libXext.so.6.4.0
QThread   10551 10553     daniel  mem       REG              254,1    650808     528743 /usr/lib/x86_64-linux-gnu/libfreetype.so.6.8.1
QThread   10551 10553     daniel  mem       REG              254,1    225128     530292 /usr/lib/x86_64-linux-gnu/libfontconfig.so.1.5.0
QThread   10551 10553     daniel  mem       REG              254,1     38768     528479 /usr/lib/x86_64-linux-gnu/libXrender.so.1.3.0
QThread   10551 10553     daniel  mem       REG              254,1    158640     524445 /lib/x86_64-linux-gnu/libpng12.so.0.49.0
QThread   10551 10553     daniel  mem       REG              254,1    238848     524304 /usr/lib/x86_64-linux-gnu/libjpeg.so.8.4.0
QThread   10551 10553     daniel  mem       REG              254,1    136936     525116 /lib/x86_64-linux-gnu/ld-2.13.so
QThread   10551 10553     daniel  mem       REG              254,1     34128       6013 /var/cache/fontconfig/945677eb7aeaf62f1d50efc3fb3ec7d8-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1     35304       6008 /var/cache/fontconfig/6d41288fd70b0be22e8c3a91e032eec0-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1     10624       6018 /var/cache/fontconfig/de9486f0b47a4d768a594cb4198cb1c6-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1     28448       5999 /var/cache/fontconfig/3f7329c5293ffd510edef78f73874cfd-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1     13288       6016 /var/cache/fontconfig/6386b86020ecc1ef9690bb720a13964f-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1      5536       5995 /var/cache/fontconfig/099525ddca5eae4f2477b69cf2d7f16d-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1      5544       5998 /var/cache/fontconfig/61092ac79d9058a69eda095afa0a78f1-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1      5856       5997 /var/cache/fontconfig/a722efc6911bbe16667b1a77497ffd37-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1      5776       5996 /var/cache/fontconfig/d63fdd8e0f42559533dd777c334fdfcc-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1     33848      14694 /var/cache/fontconfig/e13b20fdb08344e0e664864cc2ede53d-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1    115808       6014 /var/cache/fontconfig/44f970ff9b6a3db194ffc7bb3ea380d6-le64.cache-3
QThread   10551 10553     daniel  mem       REG              254,1   1534672     524749 /usr/lib/locale/locale-archive
QThread   10551 10553     daniel  mem       REG              254,1     26066     525139 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
QThread   10551 10553     daniel    0u      CHR              136,5       0t0          8 /dev/pts/5
QThread   10551 10553     daniel    1u      CHR              136,5       0t0          8 /dev/pts/5
QThread   10551 10553     daniel    2u      CHR              136,5       0t0          8 /dev/pts/5
QThread   10551 10553     daniel    3r      DIR              254,1     20480     278953 /usr/share/bash-completion/completions
QThread   10551 10553     daniel    4r     FIFO                0,8       0t0    5411455 pipe
QThread   10551 10553     daniel    5w     FIFO                0,8       0t0    5411455 pipe
QThread   10551 10553     daniel    6r     FIFO                0,8       0t0    5411458 pipe
QThread   10551 10553     daniel    7w     FIFO                0,8       0t0    5411458 pipe
QThread   10551 10553     daniel    8r     FIFO                0,8       0t0    5410750 pipe
QThread   10551 10553     daniel    9w     FIFO                0,8       0t0    5410750 pipe
QThread   10551 10553     daniel   10r     FIFO                0,8       0t0    5410751 pipe
QThread   10551 10553     daniel   11w     FIFO                0,8       0t0    5410751 pipe
QThread   10551 10554     daniel  cwd       DIR             254,33      4096     131073 /home/daniel
QThread   10551 10554     daniel  rtd       DIR              254,1      4096          2 /
QThread   10551 10554     daniel  txt       REG              254,1 206123457      13977 /usr/local/bin/wkhtmltopdf
QThread   10551 10554     daniel  mem       REG              254,1     22928     525115 /lib/x86_64-linux-gnu/libnss_dns-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     47616     525095 /lib/x86_64-linux-gnu/libnss_files-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     80712     525117 /lib/x86_64-linux-gnu/libresolv-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1   2048512     524707 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0
QThread   10551 10554     daniel  mem       REG              254,1    392072     529331 /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0
QThread   10551 10554     daniel  mem       REG              254,1     14392     527992 /usr/lib/x86_64-linux-gnu/gconv/UTF-16.so
QThread   10551 10554     daniel  mem       REG              254,1     20648     529691 /usr/lib/x86_64-linux-gnu/libXdmcp.so.6.0.0
QThread   10551 10554     daniel  mem       REG              254,1     10896     530228 /usr/lib/x86_64-linux-gnu/libXau.so.6.0.0
QThread   10551 10554     daniel  mem       REG              254,1    129840     530395 /usr/lib/x86_64-linux-gnu/libxcb.so.1.1.0
QThread   10551 10554     daniel  mem       REG              254,1    169992     524349 /lib/x86_64-linux-gnu/libexpat.so.1.6.0
QThread   10551 10554     daniel  mem       REG              254,1   1599504     525100 /lib/x86_64-linux-gnu/libc-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     89056     524448 /lib/x86_64-linux-gnu/libgcc_s.so.1
QThread   10551 10554     daniel  mem       REG              254,1    530736     525093 /lib/x86_64-linux-gnu/libm-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1    991600     529428 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.17
QThread   10551 10554     daniel  mem       REG              254,1    131107     525119 /lib/x86_64-linux-gnu/libpthread-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     31744     525118 /lib/x86_64-linux-gnu/librt-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     14768     525110 /lib/x86_64-linux-gnu/libdl-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     92752     524421 /lib/x86_64-linux-gnu/libz.so.1.2.7
QThread   10551 10554     daniel  mem       REG              254,1   1289744     528981 /usr/lib/x86_64-linux-gnu/libX11.so.6.3.0
QThread   10551 10554     daniel  mem       REG              254,1     74408     529698 /usr/lib/x86_64-linux-gnu/libXext.so.6.4.0
QThread   10551 10554     daniel  mem       REG              254,1    650808     528743 /usr/lib/x86_64-linux-gnu/libfreetype.so.6.8.1
QThread   10551 10554     daniel  mem       REG              254,1    225128     530292 /usr/lib/x86_64-linux-gnu/libfontconfig.so.1.5.0
QThread   10551 10554     daniel  mem       REG              254,1     38768     528479 /usr/lib/x86_64-linux-gnu/libXrender.so.1.3.0
QThread   10551 10554     daniel  mem       REG              254,1    158640     524445 /lib/x86_64-linux-gnu/libpng12.so.0.49.0
QThread   10551 10554     daniel  mem       REG              254,1    238848     524304 /usr/lib/x86_64-linux-gnu/libjpeg.so.8.4.0
QThread   10551 10554     daniel  mem       REG              254,1    136936     525116 /lib/x86_64-linux-gnu/ld-2.13.so
QThread   10551 10554     daniel  mem       REG              254,1     34128       6013 /var/cache/fontconfig/945677eb7aeaf62f1d50efc3fb3ec7d8-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1     35304       6008 /var/cache/fontconfig/6d41288fd70b0be22e8c3a91e032eec0-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1     10624       6018 /var/cache/fontconfig/de9486f0b47a4d768a594cb4198cb1c6-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1     28448       5999 /var/cache/fontconfig/3f7329c5293ffd510edef78f73874cfd-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1     13288       6016 /var/cache/fontconfig/6386b86020ecc1ef9690bb720a13964f-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1      5536       5995 /var/cache/fontconfig/099525ddca5eae4f2477b69cf2d7f16d-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1      5544       5998 /var/cache/fontconfig/61092ac79d9058a69eda095afa0a78f1-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1      5856       5997 /var/cache/fontconfig/a722efc6911bbe16667b1a77497ffd37-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1      5776       5996 /var/cache/fontconfig/d63fdd8e0f42559533dd777c334fdfcc-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1     33848      14694 /var/cache/fontconfig/e13b20fdb08344e0e664864cc2ede53d-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1    115808       6014 /var/cache/fontconfig/44f970ff9b6a3db194ffc7bb3ea380d6-le64.cache-3
QThread   10551 10554     daniel  mem       REG              254,1   1534672     524749 /usr/lib/locale/locale-archive
QThread   10551 10554     daniel  mem       REG              254,1     26066     525139 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
QThread   10551 10554     daniel    0u      CHR              136,5       0t0          8 /dev/pts/5
QThread   10551 10554     daniel    1u      CHR              136,5       0t0          8 /dev/pts/5
QThread   10551 10554     daniel    2u      CHR              136,5       0t0          8 /dev/pts/5
QThread   10551 10554     daniel    3r      DIR              254,1     20480     278953 /usr/share/bash-completion/completions
QThread   10551 10554     daniel    4r     FIFO                0,8       0t0    5411455 pipe
QThread   10551 10554     daniel    5w     FIFO                0,8       0t0    5411455 pipe
QThread   10551 10554     daniel    6r     FIFO                0,8       0t0    5411458 pipe
QThread   10551 10554     daniel    7w     FIFO                0,8       0t0    5411458 pipe
QThread   10551 10554     daniel    8r     FIFO                0,8       0t0    5410750 pipe
QThread   10551 10554     daniel    9w     FIFO                0,8       0t0    5410750 pipe
QThread   10551 10554     daniel   10r     FIFO                0,8       0t0    5410751 pipe
QThread   10551 10554     daniel   11w     FIFO                0,8       0t0    5410751 pipe
$ ls -la /proc/10551/fd
total 0
dr-x------ 2 daniel daniel  0 May 20 19:49 .
dr-xr-xr-x 8 daniel daniel  0 May 20 19:47 ..
lrwx------ 1 daniel daniel 64 May 20 19:49 0 -> /dev/pts/5
lrwx------ 1 daniel daniel 64 May 20 19:49 1 -> /dev/pts/5
lrwx------ 1 daniel daniel 64 May 20 19:49 2 -> /dev/pts/5
lr-x------ 1 daniel daniel 64 May 20 19:49 3 -> /usr/share/bash-completion/completions
lr-x------ 1 daniel daniel 64 May 20 19:49 4 -> pipe:[5411455]
l-wx------ 1 daniel daniel 64 May 20 19:49 5 -> pipe:[5411455]
lr-x------ 1 daniel daniel 64 May 20 19:49 6 -> pipe:[5411458]
l-wx------ 1 daniel daniel 64 May 20 19:49 7 -> pipe:[5411458]
lr-x------ 1 daniel daniel 64 May 20 19:49 8 -> pipe:[5410750]
l-wx------ 1 daniel daniel 64 May 20 19:49 9 -> pipe:[5410750]
lr-x------ 1 daniel daniel 64 May 20 19:49 10 -> pipe:[5410751]
l-wx------ 1 daniel daniel 64 May 20 19:49 11 -> pipe:[5410751]

Note there are no open network connections. My tests show that all page assets are delivered by the web server when wkhtmltopdf hangs. The output from an attempt that hangs shows none of my debug output from javascript, so it seems the hang happens after all page assets are downloaded and before javascript starts.

It's also apparent that wkhtmltopdf is threaded. I didn't find the word "thread" anywhere in the src directory, so I'm guessing this is happening implicitly in Qt. Not sure if this is relevant, but thread #4 is always in pthread_cond_wait() when the hang happens, which I suppose could indicate a deadlock:

(gdb) info thread
  Id   Target Id         Frame 
  4    Thread 0x7fd66d861700 (LWP 7870) "wkhtmltopdf" 0x00007fd66eded344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  3    Thread 0x7fd66cf50700 (LWP 7871) "QThread" 0x00007fd66e38d453 in select () from /lib/x86_64-linux-gnu/libc.so.6
  2    Thread 0x7fd667fff700 (LWP 7872) "QThread" 0x00007fd66e38d453 in select () from /lib/x86_64-linux-gnu/libc.so.6
* 1    Thread 0x7fd6708b5720 (LWP 7869) "wkhtmltopdf" 0x00007fd66e38d453 in select () from /lib/x86_64-linux-gnu/libc.so.6

I'm currently trying to find a public web site that causes the hang. I can't use my site since it requires very specific steps to stage the session which produces the page to be rendered to PDF. The page also contains customer data, so even if I was willing to stage it, I could not expose that for the sake of troubleshooting a bug.

AnthonyAkentiev commented 9 years ago

Do you have any ideas - why on Mac OS X it works fine? I am currently running fully updated Mac and wkhtmltopdf never hanged.

DanielCeregatti commented 9 years ago

I can't help but wonder if the problem is strictly javascript related. If perhaps some file isn't being loaded, and that causes javascript to never run. The fact that I'm using --window-status means that wkhtmltopdf will always wait until that's set, even if it has to wait forever, since there's no option for a global timeout. It makes sense that it would be waiting for that in the while() loop in converter.cc.

Speaking of that while() loop, one bad thing that I've noticed is that there is no delay in that loop. Its thread runs at 100% CPU, even though nothing is really happening. This begs the question: Why doesn't wkhtmltopdf use QApplication::exec()? Every Qt example that I've seen uses it to start event processing. I really feel that running your own loop and calling QApplication::processEvents() is not an intended use of Qt. I've even read on the Qt forums that calling QApplication::processEvents() in a loop is dangerous, in that it can create more events, which can then create an infinite loop. Presumably that's the case when using QApplication::exec() though, but still, I feel that not using exec() is wrong.

Regardless, I really feel that more debugging output is needed from wkhtmltopdf. It really needs to report things like requests made to retrieve page assets and how long they took, when the window.onload event is fired, etc.. It would help in figuring this out.

ashkulz commented 9 years ago

@DanielCeregatti: the reason QApplication::exec isn't used because of the libwkhtmltox bindings. In a command-line application, it is quite easy to have a blocking call to exec() but not acceptable in a library call to wkhtmltopdf_init. If that can be solved (possibly via a refactoring of the current codebase) then a local event loop via QEventLoop can be created to simulate the same blocking behavior without the high CPU usage.

Were you able to diagnose your problem?

DanielCeregatti commented 9 years ago

I was not. I'm still seeing wkhtmltopdf hang while loading our pages. Given that the loop runs millions of times, and without being able to easily trace through the code to see exactly what it's doing, it became extremely difficult to determine exactly what was causing it to hang. I can tell you this much: The hang always happens before window.onload triggers in the document. My guess is some page asset that never loads. Is there an internal timeout set for the retrieval of page assets? I haven't looked into this, but it seems likely.

The flip side of potentially blocking Qt's event loop by using exec() seems to have been the introduction of an infinite loop, from which the library would certainly also suffer. It seems that either way there's a problem here.

Would it be possible to add a usleep() call inside the loop to keep the CPU load down? Otherwise this is pretty much a runaway thread when no events are processed.

If there is anything else you can suggest, please let me know. We're committed to using wkhtmltopdf, so I'd like to do anything I can to help.

ashkulz commented 9 years ago

Does removing the --window-status option stop all the hangs? You can uncomment src/lib/multipageloader.cc:290 and see if it is the reason.

lndigo commented 9 years ago

It appears that I'm having a similar issue to Daniel. My thread information matches his when wkhtmltopdf hangs on the loading pages. Interestingly enough, when I render the same webpage the majority of the time it works and occasionally it hangs. So I have disabled javascript and it no longer hangs. For my purposes, I require javascript on the page, but this might help isolate the issue.

Fedora 21, wkhtmltopdf 0.12.2.1

ashkulz commented 9 years ago

@Indigo: can you post a reproducible test case and command-line parameters? It is hard to fix an issue if you can't reproduce it...

Yunatan commented 9 years ago

@ashkulz, I have the same issue, here the reproducible example: wkhtmltoimage.exe -f png "http://finance.yahoo.com/q/hp?s=VLDI&a=5&d=5&f=2015&e=1&c=2015&b=1&g=d" "result.png"

As said above, it stops hanging with -n (--disable-javascript) parameter.

lndigo commented 9 years ago

@ashkulz Could I send them to you via email?

lndigo commented 9 years ago

@ashkulz

I've found some interesting information. First, @DanielCeregatti is correct that it is hanging in 

bool ConverterPrivate::convert().

in qcoreapplication.cpp:1510

if (data->postEventList.size() == 0 || (receiver && !receiver->d_func()->postedEvents)) {
        --data->postEventList.recursion;
        return;
    }

postEventList.size() always equals zero, which means no events are being posted to its queue, which means 

void PdfConverterPrivate::printDocument()

will never be called and therefore convertionDone will never be true. I traced through wkhtmltox and qt and it appeared to be hanging during the http socket communication so I ran wireshark and captured the traffic. I'm confident that it appears to hang when wkhtmltox sends the webserver a reset packet for an unknown reason. This happens after wkhtmltox receives GET request response with 200 OK. I can only assume the socket is then closed and the thread terminates, leaving wkhtmltox waiting for events that will never come?

Example of failure http scenario: SYN SYN,ACK ACK GET ACK FIN,ACK HTTP 200 OK RST

Instead of: SYN, SYN,ACK ACK GET ACK HTTP 200 OK ACK FIN,ACK FIN,ACK ACK

ashkulz commented 9 years ago

@lndigo: are you able to reproduce it at will?

lndigo commented 9 years ago

It is intermittent but I can reproduce it after running on average 30 iterations. In my project I generate HTML and host it on a local webserver and use wkhtmltox to convert it to PDF, therefore I'm able to reproduce the error in a controlled environment.

@ashkulz It seems that the event queue should never be empty and when it is, wkhtmltox ends up in an infinite loop. I'm not sure if QT is emitting an error and wkhtmltox is not subscribed to it or if QT does not emit an error when it resets a socket. Either way, that might handle the scenario to prevent an infinite loop. What about the code below?

do {
    QCoreApplication::processEvents();
    QCoreApplication::sendPostedEvents();
} while(!convertionDone && QThreadData::current()->postEventList.size() != 0)

Edit: I've done more testing and it always hangs when QT sends a FIN,ACK when the webserver sends an ACK after QT makes a GET request. After QT's FIN,ACK the webserver sends a HTTP response and QT was expecting a FIN,ACK and so it sends a RST. I don't know why QT is sending a FIN,ACK before the HTTP response is delivered.

Edit 2: I rebuilt with debugging enabled for qt network. It appears when qt resets the connection QNativeSocketEnginePrivate::nativeRead encounters an EAGAIN errno and then proceeds to reset the connection. Maybe patch so QT doesn't reset the connection on EAGAIN?

DanielCeregatti commented 9 years ago

I have suspected that some sort of network issue or failed request was at fault here. The pages that I'm rendering can perform as many as 300 requests in our development environment for the javascript files, css files, image files, as well as XMLHttpRequests for asynchronous data. In production we serve a single combined file for javascript and css files, so the total number of files is substantially smaller there.

Anyhow, I have been able to consistently reproduce the problem by killing the web server that's serving the pages (in my case apache) with SIGKILL while wkhtmltopdf is still getting the page's files. Once killed, wkhtmltopdf will output that it was not able to download the files and hang. I've removed the URL from the following output because this is a business site that is not open to the public, so using the actual URLs would not help troubleshoot the problem. Here's the output:

$ wkhtmltopdf  --load-error-handling abort --debug-javascript --cookie SESSIONID 689316CD46A9396C06C23E6D94CA4FE4 --window-status waitEvent --orientation Portrait "URL REDACTED" test.pdf
Loading pages (1/6)
Warning: URL REDACTED/jquery-migrate-1.2.1.js:6 JQMIGRATE: Logging is active
Error: Failed to load URL REDACTED/file1.js, with code: 1002 (sometimes it will work just to ignore this error with --load-media-error-handling ignore)
Error: Failed to load URL REDACTED/file2.js, with code: 1002 (sometimes it will work just to ignore this error with --load-media-error-handling ignore)
... (This list is quite large, so it's truncated)
Warning: undefined:0 ReferenceError: Can't find variable: someVariable
Warning: undefined:0 ReferenceError: Can't find variable: someOtherVariable
[============================================================] 100%

At this point wkhtmltopdf is hung. This is reproducible 100% of the time as long as you catch wkhtmltopdf trying to load the page's files when you SIGKILL the web server. Here's a backtrace:

(gdb) bt
#0  0x00007fe39295b48d in nanosleep () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007fe392985b74 in usleep () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00000000004295b3 in wkhtmltopdf::ConverterPrivate::convert (this=0x4731910) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:97
#3  0x00000000004297fb in wkhtmltopdf::Converter::convert (this=0x7fff8f590400) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:153
#4  0x0000000000450206 in main (argc=15, argv=0x7fff8f590588) at /home/daniel/wkhtmltopdf/src/pdf/wkhtmltopdf.cc:187
(gdb) f 2
#2  0x00000000004295b3 in wkhtmltopdf::ConverterPrivate::convert (this=0x4731910) at /home/daniel/wkhtmltopdf/src/lib/converter.cc:97
warning: Source file is more recent than executable.
97                      usleep (100000);
(gdb) l
92              convertionDone=false;
93              beginConvert();
94              while (!convertionDone) {
95                      QCoreApplication::processEvents();
96                      QCoreApplication::sendPostedEvents();
97                      usleep (100000);
98              }
99              return !error;
100     }
101

I'm using the fix-hangs branch with some additional code:

diff --git a/src/lib/converter.cc b/src/lib/converter.cc
index 6dba2ff..ddee751 100644
--- a/src/lib/converter.cc
+++ b/src/lib/converter.cc
@@ -23,6 +23,7 @@
 #include "multipageloader.hh"
 #include <QWebFrame>
 #include <qapplication.h>
+#include <unistd.h>

 #ifdef QT4_STATICPLUGIN_TEXTCODECS
 #include <QtPlugin>
@@ -93,6 +94,7 @@ bool ConverterPrivate::convert() {
        while (!convertionDone) {
                QCoreApplication::processEvents();
                QCoreApplication::sendPostedEvents();
+               usleep (100000);
        }
        return !error;
 }

I added that usleep() because there's absolutely no reason to let that loop run away as it does. I've asked a few Qt developers about not using QApplication::exec() and they all say there is never a reason to NOT use it. The fact that you're using it in a library does not mean running QApplication::processEvents() in a loop provides you anything that QApplication::exec() doesn't. In fact, I argue that it's worse, because you end up with a runaway loop when your exit condition isn't met, which not only blocks, but consumes 100% of a CPU core.

ashkulz commented 9 years ago

@DanielCeregatti: using QApplication::exec isn't simple, as this effectively means that calls to wkhtmltopdf_init would never return. This part of wkhtmltopdf was written in the Qt 4.4 timeframe, so some of the solutions available now did not really exist or work properly then. I want to change it but don't really have the time for it right now...

On the network-related issue, can you check if it reproducible with 0.13? Looks like Qt's network stack is not delivering some signals ... does putting a printf in PdfConverterPrivate::pagesLoaded tell you if it has been reached?

lndigo commented 9 years ago

Yes, this is reproducible in 0.13 and I'm also using the fix hangs branch. When the network issue is encountered, pagesLoaded is never called. It becomes stuck in the loop with no events and no way to exit the loop.

I've never used qt before and I primarily develop on windows platforms so forgive my lack of understanding of the qt framework.

ashkulz commented 9 years ago

Thanks for the confirmation. So what happens is that fail never gets called and the loop remains running.

DanielCeregatti commented 9 years ago

Yes, as a runaway thread using 100% of a CPU core, forever.

ashkulz commented 9 years ago

Can you change dumpFrameLoaderCallbacks and dumpResourceLoadCallbacks to true around line 172 in qt/src/3rdparty/webkit/Source/WebKit/qt/WebCoreSupport/FrameLoaderClientQt.cpp? Please paste the output, as Qt does not seem to be firing an event -- I suspect it is mostly due to dispatchDidFailLoading not emitting a Qt signal. If that is the case, catching it will ensure that we call fail() and hence getting out of the loop.

Ideally, I'd love to have a comparison of

ashkulz commented 9 years ago

@lndigo, @DanielCeregatti: any luck with the above procedure for getting diagnostics?

DanielCeregatti commented 9 years ago

I haven't had a chance yet. I'll get to this some time after the holiday weekend here in the US.

lndigo commented 9 years ago

@ashkulz

When the socket gets an EAGAIN from the read syscall, webkit never finishes loading the frame, so catching a dispatchDidFailLoading doesn't seem to work since it is never emitted. It seems that QNetworkAccessManager would provide a means to check for socket errors via the finished() and error() signal but it seems that the socket error does not get propogated up the chain from the from lower level classes like QIODevice\QNativeSocketEngine and QHttpConnectionChannel, since the error is not available from a QNetworkReply object via QNetworkAccessManager.

I delved into the webkit webcore trying to ascertain whether we could detect an error as an ErrorPageExtension and pass it to a subclassed QWebPage but as it currently stands the extension is never called despite being enabled in supportsExtension. The code is quite complex and I was unable to determine a suitable location for a patch that would recognize the network error I was having and pass it to the page extension.

The fact that this error is happening all the way down in QIODevice/QAbstractSocket makes it difficult to solve the problem via inheritance.

Preliminary results show by modifying qnativesocketengine_unix.cpp QNativeSocketEnginePrivate::nativeRead, setting r = 0 in case EAGAIN will cause an error to be recognized by Qt; Qt handles it as an unexpected EOF and resends the current request which is desirable behavior. I don't know if this solution will work for @DanielCeregatti but it appears to work for my purposes.

I don't like patches that do not maintain the original intentions of the author and I'm sure causing an unexpectedEOF on any EAGAIN is not the cleanest way to solve the problem.

In addition, this is not an issue limited to wkhtmltox as I have reproduced it with Qt5.4.2 inside a QApplication:exec main loop, where it still produces a runaway thread.

DanielCeregatti commented 9 years ago

I don't see why it would not work for me. As I've said before, I've suspected something like this was the problem all along. I'll give this a try as soon as I can. Good job hunting this down!

ashkulz commented 9 years ago

@Indigo: can you share your testcase? I'll try to push it upstream, possibly getting good feedback on the approach to be taken.

lndigo commented 9 years ago

@ashkulz My test case is part of a project I've been developing internally for my employer. I don't feel comfortable sharing it publicly for privacy reasons but I could send you a working test case so that you can attempt to reproduce the bug and test the patch. If that is acceptable, send me a pm with contact information.

ashkulz commented 9 years ago

@Indigo: my email address is in my profile. Is it the pure Qt test case (what you referred to above) or one under wkhtmltopdf?

DanielCeregatti commented 9 years ago

Pardon my ignorance, but I'm not very well versed in github. How exactly is this being addressed? It seems this bug is being sent upstream to the Qt people? Is there a bug report upstream that I can track?

I've built a new wkhtmltopdf with r = 0 set for EAGAIN in qnativesocketengine_unix.cpp but I've not had any chance to test. It seems to me this is really just a band-aid for the problem and that the final fix will be coming from upstream.

Please clarify.

lndigo commented 9 years ago

@DanielCeregatti I sent @ashkulz my test case so that he can attempt to reproduce it.

I'm not sure what effect my patch would have on other projects and I agree that there exists a better solution that does not change the authors original intent. In my project, however, when the socket returns an EAGAIN from a read call, webkit never finishes loading the intended resource and therefore never finishes loading the frame, which leads me to an infinite loop.

You could attempt to patch the webkit engine, if the error is indeed in there, but I'm not familiar enough with the webkit engine to begin to make modifications to it. Additionally, webkit is being deprecated as of Qt5.5 so I see this as a fruitless endeavor.

If the error is not in the webkit engine, then it would need to be in the network access/socket code. But receiving an EAGAIN from a socket read is not an error and it's not an exception. So modifying the network code to report an EAGAIN as an error is not the correct solution either.

Additionally, none of this addresses the issue that the scenario only manifests when javascript is present.

Ultimately, by returning 0 on EAGAIN in nativeRead, Qt immediately resends the request for the resource for me and continues to load the frame uninhibited. Honestly, I couldn't ask for a better fix as I don't need notification of it, I just need it handled. Unfortunately, I don't have time on my side and for my purposes, the solution works but I understand reluctance to accept a solution that neglects to address the root problem: why is webkit not finishing loading the frame. This is @ashkulz project and I too would want to fix the root problem and not apply a band-aid.

I'm curious if my proposed fix works for your project @DanielCeregatti since that will at least verify whether we are experiencing the same issue. I'll continue to monitor this thread as I am interested in the final results and will assist in resolving the issue as time allows.

ashkulz commented 9 years ago

If this is an error with the networking code, then the testcase mentioned above

In addition, this is not an issue limited to wkhtmltox as I have reproduced it with Qt5.4.2 inside a QApplication:exec main loop, where it still produces a runaway thread.

would be very useful to report/fix upstream. I'll try to track down the issue with the wkhtmltopdf test case given by @Indigo, but finding the root cause may take some time. Will keep you posted if I find anything.

DanielCeregatti commented 9 years ago

@Indigo Your fix does not work for me. Any time EAGAIN is encountered, the file it was retrieving fails to download. Here's my diff against wkhtmltopdf/qt@4be9ebb:

diff --git a/src/network/socket/qnativesocketengine_unix.cpp b/src/network/socket/qnativesocketengine_unix.cpp
index 4bd9f98..94a0ec4 100644
--- a/src/network/socket/qnativesocketengine_unix.cpp
+++ b/src/network/socket/qnativesocketengine_unix.cpp
@@ -1039,7 +1039,8 @@ qint64 QNativeSocketEnginePrivate::nativeRead(char *data, qint64 maxSize)
 #endif
         case EAGAIN:
             // No data was available for reading
-            r = -2;
+            qDebug("EAGAIN...");
+            r = 0;
             break;
         case EBADF:
         case EINVAL:

And here's a test run:

wkhtmltopdf --enable-javascript --load-error-handling abort --debug-javascript --cookie SESSIONID C264BAECF62C985CEBA9A9686EB5B942 --window-status waitEvent --orientation Landscape "URL REDACTED" test.pdf
Loading pages (1/6)
EAGAIN...                                                    ] 10%
EAGAIN...
EAGAIN...
EAGAIN...
EAGAIN...                                                    ] 10%
EAGAIN...
EAGAIN...
EAGAIN...
Warning: Failed to load URL_REDACTED/css/crossover.css (ignore)
Warning: Failed to load URL_REDACTED/css/notification.css (ignore)
Warning: URL_REDACTED/js/000_jquery/jquery-migrate-1.2.1.js:6 JQMIGRATE: Logging is active
EAGAIN...
Counting pages (2/6)
Resolving links (4/6)                                                       
Loading headers and footers (5/6)                                           
Printing pages (6/6)
Done                                                                      
Exit with code 1 due to network error: RemoteHostClosedError

A pdf is generated in this case, but since 2 CSS files didn't download, it's missing a lot of styling. On occasions where the files that fail to download are javascript files, the waitEvent never happens, as javascript never runs successfully.

One thing I've noticed is that despite setting "--load-error-handling abort", these events are always ignored. I'm guessing this is not what's supposed to happen?

Anyhow, can you post your test program where you reproduced this issue in Qt 5.4.2? I know a few people who write Qt applications and I'd like them to verify this and get it sent upstream once it's been verified.

lndigo commented 9 years ago

@DanielCeregatti I was hopeful that the fix would work for you, looks like it's more complicated than I was hoping. Based on your response, can I assume that wkhtmltox no longer hangs? If that is the case, then I suppose this is at least progress, since now Qt is emitting errors instead of becoming a runaway thread.

In your instance, there is a counter that is initialized to 2, that decrements each time a resend request occurs, which setting r = 0 causes a resend request. Therefore, it appears to resend the request 3 times before failure. I suppose you could increase the initial value of the counter to increase the fault tolerance, however, I agree that the patching nativeRead is not going to be the solution. For curiosity's sake, I would be interested in what would happen if you increased the reconnectAttempts and if there exists a reasonable value that achieves a high success rate. Now, I'm not suggesting that is a fix, but I would like to know if it is a temporal communication issue between Qt and the webserver and perhaps by increasing the reconnectAttempts might extend the duration of the request window.

Lastly, I know everyone is busy and wants this problem solved. If @ashkulz is able to reproduce it with my source I'll send it to you @DanielCeregatti to submit to your colleagues. Oddly enough, when reducing the test case to its smallest size, I can get the error to occur even with no javascript being executed on the page. Makes me wonder about the JSLexer and maybe if I've wrote some funky javascript that it does not like...

ashkulz commented 9 years ago

I was not able to reproduce the error with the test case given by @Indigo. I tried the method given by @DanielCeregatti (killing the webserver while it is loading the page) -- created a 300kB file with just <br><hr> and used a rate limit of 1kB/sec with extended_http_server.py. For me, it just gave:

Loading pages (1/6)
Warning: SSL error ignored                                        
Error: Failed loading page https://localhost:8000/test.html (sometimes it will work just to ignore this error with --load-error-handling ignore)
Exit with code 1 due to network error: RemoteHostClosedError

So, I'm stumped. I can kind of understand the error path, but without being able to reproduce the error I can't really fix it inside Qt and/or WebKit (which is where it should ideally be fixed).

DanielCeregatti commented 9 years ago

It is still my opinion that the underlying problem is the fact that javascript execution is interrupted or never started at all. In all test cases except the original few, --window-status is used. If javascript never sets the page's window.status when --window-status is used, wkhtmltopdf will hang indefinitely. For me the use of --window-status is mandatory, as our pages take a varying amount of time to load and I don't want to take a chance at having an incomplete pdf by using an arbitrary timer. Please retry your test with many script tags for javascript files and cause one of those to fail, along with --window-status. It will definitely hang.

@ashkulz @lndigo Can you please provide me with the Qt test case? If it can be shown that this is an upstream bug, it would go a long way in solving the problem, as I have the attention of a few Qt developers that can easily confirm if that is a valid test.

Edit: Apparently github comments break if you use <script> (without HTML entities) in a comment...

ashkulz commented 9 years ago

If there is a JS loading error and it hangs because of --window-status, that's a separate issue ... very easy to reproduce but essentially unsolvable. @Indigo hasn't shared the Qt test case and you seem to suggest that your scenario is caused by using --window-status ... so did you ever get a hang without it?

DanielCeregatti commented 9 years ago

I have no cases where I would use wkhtmltopdf without --window-status, so conducting such a test is futile for me. In my opinion, this bug is legitimate, but the underlying issue has not yet been entirely identified. My suspicion has always been that there is some sort of network error that's causing files to be omitted. @lndigo has alluded to this. This causes wkhtmltopdf to either never start javascript execution (such as omitting the file that handles winow.onload) or causes a javascript error which then prevents the code that sets window.status from running. I agree that this only affects people using --window-status.

I also agree with your assessment regarding the issue of tracking javascript execution as being "unsolvable". The problem remains though: wkhtmltopdf randomly hangs when --window-status is specified.

To be clear, I've conducted extensive testing on pages that I have loaded in Chrome hundreds of times and window.status is always set, yet wkhtmltopdf randomly does not start javascript on the exact same page. I have added a lot of console.log() calls to my javascript code to denote things like window.onload firing, asynchronous events happening, as well as window.status being set. When wkhtmltopdf hangs, no javascript output is ever seen, and accordingly, window.status is never set. So it's safe to conclude the hang is due to wkhtmltopdf waiting for window.status to be set when it's never going to be set.

At this time I'm going restate what I mentioned in an earlier comment: wkhtmltopdf needs more debugging output as well as more debugging features. It needs:

I've been granted more time to dig into this issue but I'm not sure how much more help I can offer given my limited understanding of C++. I'll report what I find as soon as I find it. That being said, I've been encountering some build issues recently. I can no longer build on my Debian Jessie machine. Even the master branch of a clean clone fails when building ruby gems in preparation for creating the chroot. I'll report more once I have more information.

DanielCeregatti commented 9 years ago

Here's the build issue:

$ cat /etc/debian_version
8.1
$ sudo scripts/build.py setup-schroot-wheezy
...
lots of GETing
...
Building native extensions.  This could take a while...
/usr/bin/ruby2.1 extconf.rb
checking for ffi.h... *** extconf.rb failed ***
Could not create Makefile due to some reason, probably lack of necessary
libraries and/or headers.  Check the mkmf.log file for more details.  You may
need configuration options.

Provided configuration options:
        --with-opt-dir
        --without-opt-dir
        --with-opt-include
        --without-opt-include=${opt-dir}/include
        --with-opt-lib
        --without-opt-lib=${opt-dir}/lib
        --with-make-prog
        --without-make-prog
        --srcdir=.
        --curdir
        --ruby=/usr/bin/ruby2.1
        --with-ffi_c-dir
        --without-ffi_c-dir
        --with-ffi_c-include
        --without-ffi_c-include=${ffi_c-dir}/include
        --with-ffi_c-lib
        --without-ffi_c-lib=${ffi_c-dir}/lib
        --with-libffi-config
        --without-libffi-config
        --with-pkg-config
        --without-pkg-config
/usr/lib/ruby/2.1.0/mkmf.rb:456:in `try_do': The compiler failed to generate an executable file. (RuntimeError)
You have to install development tools first.
        from /usr/lib/ruby/2.1.0/mkmf.rb:587:in `try_cpp'
        from /usr/lib/ruby/2.1.0/mkmf.rb:1067:in `block in have_header'
        from /usr/lib/ruby/2.1.0/mkmf.rb:918:in `block in checking_for'
        from /usr/lib/ruby/2.1.0/mkmf.rb:351:in `block (2 levels) in postpone'
        from /usr/lib/ruby/2.1.0/mkmf.rb:321:in `open'
        from /usr/lib/ruby/2.1.0/mkmf.rb:351:in `block in postpone'
        from /usr/lib/ruby/2.1.0/mkmf.rb:321:in `open'
        from /usr/lib/ruby/2.1.0/mkmf.rb:347:in `postpone'
        from /usr/lib/ruby/2.1.0/mkmf.rb:917:in `checking_for'
        from /usr/lib/ruby/2.1.0/mkmf.rb:1066:in `have_header'
        from extconf.rb:16:in `<main>'
ERROR:  Error installing fpm:
        ERROR: Failed to build gem native extension.

    Building has failed. See above output for more information on the failure.
extconf failed, exit code 1

Gem files will remain installed in /var/lib/gems/2.1.0/gems/ffi-1.9.10 for inspection.
Results logged to /var/lib/gems/2.1.0/extensions/x86_64-linux/2.1.0/ffi-1.9.10/gem_make.out
gem install -V fpm -N
command failed: exit code 256
ashkulz commented 9 years ago

@DanielCeregatti: let us discuss the build issue in the linked issue instead of here. I've only tested the generic linux builds, not the distro-specific builds (and that too not on a fresh machine), hence the problem. The 0.12.3 release will only be with generic linux builds, not sure right now if the other targets will still be kept in the build script or removed.

ashkulz commented 9 years ago

wkhtmltopdf needs more debugging output as well as more debugging features. It needs:

  • To print when it starts to download a page asset file. (Image, javascript, css, whatever)
  • To print when it finishes downloading a file, along with statistics.

Those are "good to have", not essential to solving this issue.

  • An option to turn off the progress bar. It just gets in the way when you're trying to read the output.

Use the -q or --quiet option.

  • An option to exit execution with a non zero status when any page asset file fails to load. It seems that neither --load-error-handling abort and --load-media-error-handling abort do this.

That's clearly a bug, can you create a very small test case to confirm it? Please attach it to a separate issue so that it can be fixed separately.

  • An option to time the whole thing out when --window-status is used.

That's a new feature, maybe something like --window-status-timeout? Report a separate issue to track it.

I'd like to leave this issue open to identify if there truly are random hangs happening without the --window-status option, which @Indigo seems to be experiencing.

DanielCeregatti commented 9 years ago

The -q or --quiet option suppresses all output. I still need to see everything javascipt is writing to the console. I just want to suppress the progress bar.

ashkulz commented 9 years ago

Do you mean an option like --disable-progressbar which would still show all warning/error messages?

DanielCeregatti commented 9 years ago

Sorry for the long hiatus. I've been very busy.

Yes, if the progress output could be suppressed, that would be a nice feature to have. My strategy now is to simply mitigate when wkhtmltopdf hangs, and doing so involves reading its output.

I have confirmed that wkhtmltopdf can hang on simply downloading content without --window-status. It's still very hit and miss, and I can't create a consistently reproducible example.

Today I ran into this other bug report: #2234. That backtrace looks all too familiar. I'm going play around with those settings to see if they help.