Re: new errors in loolwsd.log

Hi Aditya,

On Mon, Mar 13, 2017 at 5:08 PM, Aditya Dewan <callmedewan@gmail.com> wrote:

> so, the capability issue got resolved but some new errors are now coming
> in the log file.
> I tried reading the code and searching on the internet about what might be
> causing this, but that has been of no use.

That's a very new code that got merged to master couple of days ago. It was
a big change.

Pasting the relevant lines from your log file here

wsd-22947-22950 11:17:49.361387 [ prisoner_poll ] INF  Launching forkit
> process: /media/dewan/Work/gsoc/online/loolforkit --losubpath=lo
> --systemplate=/media/dewan/Work/gsoc/online/systemplate
> --lotemplate=/media/dewan/Work/gsoc/core/instdir
> --childroot=/media/dewan/Work/gsoc/online/jails/ --clientport=9980
> --masterport=9981| wsd/LOOLWSD.cpp:1254
> wsd-22947-22950 11:17:49.361783 [ prisoner_poll ] INF  Forkit process
> launched: 22953| wsd/LOOLWSD.cpp:1265
> wsd-22947-22950 11:17:49.361852 [ prisoner_poll ] TRC  Poll completed with
> 1 live polls | ./net/Socket.hpp:312
> wsd-22947-22951 11:17:54.362998 [ prisoner_poll ] TRC  Total memory used:
> 82153| wsd/Admin.cpp:339
> wsd-22947-22950 11:17:54.366926 [ prisoner_poll ] TRC  Poll completed with
> 0 live polls timeout| ./net/Socket.hpp:312
> wsd-22947-22951 11:17:59.364337 [ prisoner_poll ] TRC  Total memory used:
> 135893| wsd/Admin.cpp:339
> wsd-22947-22950 11:17:59.372078 [ prisoner_poll ] TRC  Poll completed with
> 0 live polls timeout| ./net/Socket.hpp:312
> wsd-22947-22947 11:18:04.359872 [ loolwsd ] FTL  Failed to fork child
> processes.| wsd/LOOLWSD.cpp:2581
> wsd-22947-22951 11:18:04.365700 [ prisoner_poll ] TRC  Total memory used:
> 177414| wsd/Admin.cpp:339
> wsd-22947-22950 11:18:04.377168 [ prisoner_poll ] TRC  Poll completed with
> 0 live polls timeout| ./net/Socket.hpp:312
> wsd-22947-22947 11:18:04.391824 [ loolwsd ] INF  ~Admin dtor.|
> wsd/Admin.cpp:307
> wsd-22947-22952 11:18:04.391917 [ prisoner_poll ] DBG  Cpu stat dtor|
> wsd/Admin.hpp:155
> wsd-22947-22951 11:18:04.392085 [ prisoner_poll ] DBG  Memory stat dtor|
> wsd/Admin.hpp:132
> wsd-22947-22947 11:18:04.392179 [ loolwsd ] INF  AdminModel dtor.|
> wsd/AdminModel.hpp:148
> frk-22953-22953 11:18:13.607801 [ loolforkit ] INF  Preinit stage OK.|
> kit/ForKit.cpp:467
> frk-22953-22953 11:18:13.607893 [ loolforkit ] DBG  Forking a loolkit
> process.| kit/ForKit.cpp:224
> frk-22953-22953 11:18:13.610928 [ loolforkit ] INF  Forked kit [23006].|
> kit/ForKit.cpp:265
> frk-22953-22953 11:18:13.611058 [ loolforkit ] INF  ForKit process is
> ready.| kit/ForKit.cpp:479
> kit-23006-23006 11:18:13.611671 [ loolkit ] INF  Initializing kit. Local
> time: Mon 2017-03-13 16:48:13+0530. Log level is [8].| common/Log.cpp:173
> kit-23006-23006 11:18:13.611919 [ loolkit ] DBG  Process started.|
> kit/Kit.cpp:1592
> frk-22953-22953 11:18:13.627700 [ loolforkit ] FTL  Pipe closed.|
> common/IoUtil.cpp:330
> frk-22953-22953 11:18:13.627730 [ loolforkit ] INF  Child dispatcher
> flagged for termination.| kit/ForKit.cpp:487
> frk-22953-22953 11:18:13.627751 [ loolforkit ] INF  ForKit process
> finished.| kit/ForKit.cpp:502
> kit-23006-23006 11:18:13.635367 [ loolkit ] INF  Jail path:
> /media/dewan/Work/gsoc/online/jails/23006/| kit/Kit.cpp:1606


I don't have much idea about it, but others might have a clue here. Those
"Poll completed with 0 live polls timeout" looks the root cause to me, but
why they are there in the first place, I am not sure about.


-- 
Regards,
Pranav Kant
http://pranavk.me

frk-22953-22953 11:17:49.399927 [ loolforkit ] INF  Initializing frk. Local time: Mon 2017-03-13 
16:47:49+0530. Log level is [8].| common/Log.cpp:173
frk-22953-22953 11:17:49.400066 [ loolforkit ] INF  Have capability cap_sys_chroot| 
kit/ForKit.cpp:163
frk-22953-22953 11:17:49.400086 [ loolforkit ] INF  Have capability cap_mknod| kit/ForKit.cpp:163
frk-22953-22953 11:17:49.400097 [ loolforkit ] INF  Have capability cap_fowner| kit/ForKit.cpp:163
frk-22953-22953 11:17:49.422425 [ loolforkit ] TRC  
dlopen(/media/dewan/Work/gsoc/core/instdir/program/libsofficeapp.so, RTLD_GLOBAL|RTLD_NOW)| 
kit/Kit.cpp:1909
frk-22953-22953 11:17:52.794151 [ loolforkit ] TRC  
lok_preinit(/media/dewan/Work/gsoc/core/instdir/program", "file:///user")| kit/Kit.cpp:1938
wsd-22947-22947 11:17:49.251135 [ loolwsd ] INF  Initializing wsd. Local time: Mon 2017-03-13 
16:47:49+0530. Log level is [8].| common/Log.cpp:173
wsd-22947-22947 11:17:49.252240 [ loolwsd ] INF  SSL support: SSL is enabled.| wsd/LOOLWSD.cpp:771
wsd-22947-22947 11:17:49.252405 [ loolwsd ] INF  Maximum concurrent open Documents limit: 10| 
wsd/LOOLWSD.cpp:810
wsd-22947-22947 11:17:49.252415 [ loolwsd ] INF  Maximum concurrent client Connections limit: 20| 
wsd/LOOLWSD.cpp:811
wsd-22947-22947 11:17:49.252607 [ loolwsd ] INF  Command trace dumping enabled to file: 
/tmp/looltrace-%.gz| wsd/LOOLWSD.cpp:838
wsd-22947-22947 11:17:49.283637 [ loolwsd ] INF  Adding trusted WOPI host: [localhost].| 
wsd/Storage.cpp:86
wsd-22947-22947 11:17:49.283725 [ loolwsd ] INF  Adding trusted WOPI host: 
[10\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}].| wsd/Storage.cpp:86
wsd-22947-22947 11:17:49.283764 [ loolwsd ] INF  Adding trusted WOPI host: 
[172\.1[6789]\.[0-9]{1,3}\.[0-9]{1,3}].| wsd/Storage.cpp:86
wsd-22947-22947 11:17:49.283804 [ loolwsd ] INF  Adding trusted WOPI host: 
[172\.2[0-9]\.[0-9]{1,3}\.[0-9]{1,3}].| wsd/Storage.cpp:86
wsd-22947-22947 11:17:49.283828 [ loolwsd ] INF  Adding trusted WOPI host: 
[172\.3[01]\.[0-9]{1,3}\.[0-9]{1,3}].| wsd/Storage.cpp:86
wsd-22947-22947 11:17:49.283847 [ loolwsd ] INF  Adding trusted WOPI host: 
[192\.168\.[0-9]{1,3}\.[0-9]{1,3}].| wsd/Storage.cpp:86
wsd-22947-22947 11:17:49.283866 [ loolwsd ] INF  Adding blocked WOPI host: [192\.168\.1\.1].| 
wsd/Storage.cpp:91
wsd-22947-22947 11:17:49.284262 [ loolwsd ] INF  SSL Cert file: 
/media/dewan/Work/gsoc/online/etc/cert.pem| wsd/LOOLWSD.cpp:864
wsd-22947-22947 11:17:49.284286 [ loolwsd ] INF  SSL Key file: 
/media/dewan/Work/gsoc/online/etc/key.pem| wsd/LOOLWSD.cpp:867
wsd-22947-22947 11:17:49.284303 [ loolwsd ] INF  SSL CA file: 
/media/dewan/Work/gsoc/online/etc/ca-chain.cert.pem| wsd/LOOLWSD.cpp:870
wsd-22947-22947 11:17:49.355787 [ loolwsd ] DBG  FileServerRoot: /media/dewan/Work/gsoc/online/| 
wsd/LOOLWSD.cpp:2561
wsd-22947-22947 11:17:49.355917 [ loolwsd ] TRC  Set socket buffer size to 4608| 
./net/Socket.hpp:117
wsd-22947-22947 11:17:49.355931 [ loolwsd ] TRC  Socket #11 buffer size: 4608 (was 16384)| 
./net/Socket.hpp:222
wsd-22947-22947 11:17:49.359368 [ loolwsd ] DBG  Inserting socket #11 into prisoner_poll| 
./net/Socket.hpp:401
wsd-22947-22950 11:17:49.359603 [ prisoner_poll ] INF  Starting polling thread [prisoner_poll].| 
./net/Socket.hpp:278
wsd-22947-22950 11:17:49.359714 [ prisoner_poll ] TRC  Poll completed with 1 live polls | 
./net/Socket.hpp:312
wsd-22947-22947 11:17:49.359597 [ loolwsd ] TRC  Waiting for a new child for a max of 15000 ms.| 
wsd/LOOLWSD.cpp:2577
wsd-22947-22950 11:17:49.359743 [ prisoner_poll ] INF  Creating new forkit process.| 
wsd/LOOLWSD.cpp:1210
wsd-22947-22950 11:17:49.359864 [ prisoner_poll ] INF  AdminModel ctor.| wsd/AdminModel.hpp:143
wsd-22947-22950 11:17:49.359984 [ prisoner_poll ] INF  Admin ctor.| wsd/Admin.cpp:291
wsd-22947-22950 11:17:49.361243 [ prisoner_poll ] TRC  Total memory used: 11618| wsd/Admin.cpp:295
wsd-22947-22950 11:17:49.361272 [ prisoner_poll ] DBG  Memory stat ctor| wsd/Admin.hpp:127
wsd-22947-22950 11:17:49.361358 [ prisoner_poll ] DBG  Cpu stat ctor| wsd/Admin.hpp:150
wsd-22947-22950 11:17:49.361387 [ prisoner_poll ] INF  Launching forkit process: 
/media/dewan/Work/gsoc/online/loolforkit --losubpath=lo 
--systemplate=/media/dewan/Work/gsoc/online/systemplate 
--lotemplate=/media/dewan/Work/gsoc/core/instdir --childroot=/media/dewan/Work/gsoc/online/jails/ 
--clientport=9980 --masterport=9981| wsd/LOOLWSD.cpp:1254
wsd-22947-22950 11:17:49.361783 [ prisoner_poll ] INF  Forkit process launched: 22953| 
wsd/LOOLWSD.cpp:1265
wsd-22947-22950 11:17:49.361852 [ prisoner_poll ] TRC  Poll completed with 1 live polls | 
./net/Socket.hpp:312
wsd-22947-22951 11:17:54.362998 [ prisoner_poll ] TRC  Total memory used: 82153| wsd/Admin.cpp:339
wsd-22947-22950 11:17:54.366926 [ prisoner_poll ] TRC  Poll completed with 0 live polls timeout| 
./net/Socket.hpp:312
wsd-22947-22951 11:17:59.364337 [ prisoner_poll ] TRC  Total memory used: 135893| wsd/Admin.cpp:339
wsd-22947-22950 11:17:59.372078 [ prisoner_poll ] TRC  Poll completed with 0 live polls timeout| 
./net/Socket.hpp:312
wsd-22947-22947 11:18:04.359872 [ loolwsd ] FTL  Failed to fork child processes.| 
wsd/LOOLWSD.cpp:2581
wsd-22947-22951 11:18:04.365700 [ prisoner_poll ] TRC  Total memory used: 177414| wsd/Admin.cpp:339
wsd-22947-22950 11:18:04.377168 [ prisoner_poll ] TRC  Poll completed with 0 live polls timeout| 
./net/Socket.hpp:312
wsd-22947-22947 11:18:04.391824 [ loolwsd ] INF  ~Admin dtor.| wsd/Admin.cpp:307
wsd-22947-22952 11:18:04.391917 [ prisoner_poll ] DBG  Cpu stat dtor| wsd/Admin.hpp:155
wsd-22947-22951 11:18:04.392085 [ prisoner_poll ] DBG  Memory stat dtor| wsd/Admin.hpp:132
wsd-22947-22947 11:18:04.392179 [ loolwsd ] INF  AdminModel dtor.| wsd/AdminModel.hpp:148
frk-22953-22953 11:18:13.607801 [ loolforkit ] INF  Preinit stage OK.| kit/ForKit.cpp:467
frk-22953-22953 11:18:13.607893 [ loolforkit ] DBG  Forking a loolkit process.| kit/ForKit.cpp:224
frk-22953-22953 11:18:13.610928 [ loolforkit ] INF  Forked kit [23006].| kit/ForKit.cpp:265
frk-22953-22953 11:18:13.611058 [ loolforkit ] INF  ForKit process is ready.| kit/ForKit.cpp:479
kit-23006-23006 11:18:13.611671 [ loolkit ] INF  Initializing kit. Local time: Mon 2017-03-13 
16:48:13+0530. Log level is [8].| common/Log.cpp:173
kit-23006-23006 11:18:13.611919 [ loolkit ] DBG  Process started.| kit/Kit.cpp:1592
frk-22953-22953 11:18:13.627700 [ loolforkit ] FTL  Pipe closed.| common/IoUtil.cpp:330
frk-22953-22953 11:18:13.627730 [ loolforkit ] INF  Child dispatcher flagged for termination.| 
kit/ForKit.cpp:487
frk-22953-22953 11:18:13.627751 [ loolforkit ] INF  ForKit process finished.| kit/ForKit.cpp:502
kit-23006-23006 11:18:13.635367 [ loolkit ] INF  Jail path: 
/media/dewan/Work/gsoc/online/jails/23006/| kit/Kit.cpp:1606
kit-23006-23006 11:18:13.647358 [ loolkit ] DBG  
symlink("../../../../../lo","/media/dewan/Work/gsoc/online/jails/23006/media/dewan/Work/gsoc/core/instdir")|
 kit/Kit.cpp:268
kit-23006-23006 11:18:15.548209 [ loolkit ] TRC  skip redundant paths program/wizards| 
kit/Kit.cpp:178
kit-23006-23006 11:18:15.691392 [ loolkit ] TRC  skip redundant paths sdk| kit/Kit.cpp:178
kit-23006-23006 11:18:15.731391 [ loolkit ] TRC  skip redundant paths share/basic| kit/Kit.cpp:178
kit-23006-23006 11:18:17.118967 [ loolkit ] TRC  skip redundant paths share/config/wizard| 
kit/Kit.cpp:178
kit-23006-23006 11:18:17.327505 [ loolkit ] TRC  skip redundant paths share/gallery| kit/Kit.cpp:178
kit-23006-23006 11:18:17.372281 [ loolkit ] TRC  skip redundant paths share/Scripts| kit/Kit.cpp:178
kit-23006-23006 11:18:17.372628 [ loolkit ] TRC  skip redundant paths share/template| 
kit/Kit.cpp:178
kit-23006-23006 11:18:22.743116 [ loolkit ] DBG  Initialized jail files.| kit/Kit.cpp:1663
kit-23006-23006 11:18:22.744880 [ loolkit ] INF  
chroot("/media/dewan/Work/gsoc/online/jails/23006/")| kit/Kit.cpp:1687
kit-23006-23006 11:18:22.749712 [ loolkit ] TRC  Capabilities first: = 
cap_fowner,cap_sys_chroot,cap_mknod+ep| kit/Kit.cpp:234
kit-23006-23006 11:18:22.749822 [ loolkit ] TRC  Capabilities now: = cap_fowner,cap_mknod+ep| 
kit/Kit.cpp:251
kit-23006-23006 11:18:22.749849 [ loolkit ] TRC  Capabilities first: = cap_fowner,cap_mknod+ep| 
kit/Kit.cpp:234
kit-23006-23006 11:18:22.749872 [ loolkit ] TRC  Capabilities now: = cap_fowner+ep| kit/Kit.cpp:251
kit-23006-23006 11:18:22.749932 [ loolkit ] TRC  Capabilities first: = cap_fowner+ep| 
kit/Kit.cpp:234
kit-23006-23006 11:18:22.749957 [ loolkit ] TRC  Capabilities now: =| kit/Kit.cpp:251
kit-23006-23006 11:18:22.749968 [ loolkit ] DBG  Initialized jail nodes, dropped caps.| 
kit/Kit.cpp:1704
kit-23006-23006 11:18:23.229030 [ loolkit ] INF  Process is ready.| kit/Kit.cpp:1739
kit-23006-23006 11:18:23.290112 [ loolkit ] ERR  Poco Exception: Connection refused| 
kit/Kit.cpp:1867
kit-23006-23006 11:18:23.290166 [ loolkit ] INF  Process finished.| kit/Kit.cpp:1876