The story of an annoying bug that got nailed and fixed ;-)
eboutin
We chose Zotonic a while ago as the target framework for building our
web site.
Everything was nice and smooth while developping on our pcs (both
under Windows and Debian boxes under VirtualBox).
And then... we decided it was time to deploy Zotonic on our dedicated
server.
And then... Zotonic refused to start.
In the logs, we had something like :
=INFO REPORT==== 29-Jan-2012::14:57:07 ===
DEBUG: z_install_data:196 "Inserting username for the admin"
=INFO REPORT==== 29-Jan-2012::14:57:07 ===
Exception in transaction: "exit,{noproc,{gen_server,call,[z_ids,{id,
10}]}}"
=SUPERVISOR REPORT==== 29-Jan-2012::14:57:07 ===
Supervisor: {<0.107.0>,z_site_sup}
Context: start_error
Reason: {'EXIT',
{{badmatch,
{rollback,
{noproc,{gen_server,call,[z_ids,{id,
10}]}}}},
[{z_install,install,1},
{z_installer,start_link,1},
{supervisor,do_start_child,2},
{supervisor,start_children,3},
{supervisor,init_children,2},
{gen_server,init_it,6},
{proc_lib,init_p_do_apply,3}]}}
Offender: [{pid,undefined},
{name,z_installer},
{mfa,
{z_installer,start_link,
[[
%%%%% config removed %%%%%
]]}},
{restart_type,permanent},
{shutdown,1},
{child_type,worker}]
Google revealed that "jeff" and Michael Connors had had the same
issue :
http://groups.google.com/group/zotonic-users/browse_thread/thread/41b1eabe96717e3f
http://groups.google.com/group/zotonic-developers/browse_thread/thread/8649c87c7d11bdda
But there was no solution proposed.
Over several days we tried (almost) everything to get it right:
- zotonic 0.7.3
- zotonic 0.7.4
- hacking the code in all sorts of inventive ways
- playing with pgsql settings
- creating new dbs
- re-installing pgsql
- formatting the server and reinstalling the OS (i'm quite ashamed of
that one)
Nothing would do. And then I said to myself maybe i could use my
brains a little bit for once... doh!
Everything we had experienced was consistent with the z_ids gen_server
stopped:
{noproc,{gen_server,call,[z_ids,{id,10}]}}}},
What could have stopped the z_ids gen_server? Since z_ids is under a
supervision tree, it had to be another process that exited
prematurely.
I used the dbg module to trace process events:
dbg:tracer(),
dbg:p(all,[p]).
This logs all the spawn/exit process events. In the logs, I searched
the first occurence of exit that was not "exit normal". I got:
(<0.135.0>) unregister z_sites_manager
Terminating due to shutdown
(<0.135.0>) exit {timeout,{gen_server,call,[<0.136.0>,
{start_child,xxx}]}}
So something went wrong inside start_child and caused a time out.
I searched the spawn event that created process <0.135.0>. I got:
(<0.101.0>) spawn <0.135.0> as proc_lib:init_p(zotonic_sup,
[<0.79.0>],gen,init_it,[gen_server,<0.101.0>,<0.101.0>,
{local,z_sites_manager},
z_sites_manager,[],
[{timeout,3600000}]])
(<0.101.0>) link <0.135.0>
(<0.135.0>) register z_sites_manager
This confirmed the issue was inside z_sites_manager:start_child.
I followed the code:
In z_sites_manager:
handle_cast({start, Site}, State) ->
z_supervisor:start_child(State#state.sup, Site), ...
In z_supervisor:
start_child(Pid, Name) ->
gen_server:call(Pid, {start_child, Name}).
The gen_server documentation confirmed what i remembered:
gen_server:call can time out with a default timeout of 5s.
I realised that the dedicated server is not as powerful as our desktop
beasts. So it's normal it takes longer to populate zotonic's tables at
first startup. Definitely more than 5s.
So I changed the code in z_supervisor and recompiled:
start_child(Pid, Name) ->
gen_server:call(Pid, {start_child, Name}, infinity).
Et voilà! Zotonic started for the first time on our dedicated server
and we lived happily ever after with the shame of all the dumb things
we did to get this sorted.
Note: this last piece of code in z_supervisor is different in 0.7.3
and 0.7.4 but they both suffer from the same problem and the same fix
is applicable in both versions.
I think z_sites_manager should not assume anything regarding the time
needed by a given site to start. So it's seems perfectly logical to
have no timeout and let the site itself decide if its start time is
too much.
A better fix would be:
In z_supervisor:
start_child(Pid, Name, Timeout) ->
gen_server:call(Pid, {start_child, Name}, Timeout).
handle_cast({start, Site}, State) ->
z_supervisor:start_child(State#state.sup, Site, infinity), ...
What do you think?
Arjan Scherpenisse
thanks for your detailed report. There's nothing wrong with it, however
it might have lingered in mailing list queue for a while (we review all
messages first time somebody sends something, to prevent spam).
The issue that sometimes a site takes too long to startup is indeed very
annoying and leads to strange behaviour.
I am tempted to commit your solution (changing z_supervisor to allow a
longer startup time for childs) but I'd first like some feedback from
the other developers (Marc, Andreas, Maas?)
One more thought: choosing 'infinity' means you trust all sites (and
modules!) not to do anything stupid in their startup code: the whole
system may fail to start up if one site decides to block.
Cheers,
Arjan
On 02/11/2012 09:53 PM, Emmanuel Boutin wrote:
> Hi!
>
> I've had not feedback from my post below. Is something wrong with it?
>
> Kind regards,
>
> Emmanuel
>
> -----Message d'origine-----
> De : eboutin [mailto:emmanue...@free.fr]
> Envoy� : samedi 4 f�vrier 2012 14:52
> � : Zotonic developers
> Objet : The story of an annoying bug that got nailed and fixed ;-)
> Et voil�! Zotonic started for the first time on our dedicated server
eboutin
I understand your point: one site should not be allowed to affect the
others.
My point is that zotonic should not kill itself because of a timeout
at the z_sites_manager/z_supervisor level.
You can always have a situation where a "should be long enough"
timeout is not long enough.
So in my mind:
- if a site takes too long to start because of the zotonic code then
that's a zotonic bug and it should be fixed in zotonic
- if a site takes too long to start because of the way it behaves in
its private code, then zotonic should be able to protect itself from
bad site behaviour
Maybe one cheap way of doing this would be to have timeout checks in
place at the places where zotonic calls site code.
The timeout could then come from the site config so that the site has
a chance to say what "long enough" means for itself.
I'm not familiar enough with zotonic insides to know where those
transitions from zotonic code to site code are made.
A cheaper alternative would be to use the 'infinity' timeout only when
the site starts for the first time but I found no easy way to
implement this: we only know if the site starts for the first time
later, inside z_installer, where we have access to the site's db.
Regards,
Emmanuel
On 12 fév, 08:24, Arjan Scherpenisse <ar...@scherpenisse.net> wrote:
> Hi Emmanuel,
>
> thanks for your detailed report. There's nothing wrong with it, however
> it might have lingered in mailing list queue for a while (we review all
> messages first time somebody sends something, to prevent spam).
>
> The issue that sometimes a site takes too long to startup is indeed very
> annoying and leads to strange behaviour.
>
> I am tempted to commit your solution (changing z_supervisor to allow a
> longer startup time for childs) but I'd first like some feedback from
> the other developers (Marc, Andreas, Maas?)
>
> One more thought: choosing 'infinity' means you trust all sites (and
> modules!) not to do anything stupid in their startup code: the whole
> system may fail to start up if one site decides to block.
>
> Cheers,
> Arjan
>
> On 02/11/2012 09:53 PM, Emmanuel Boutin wrote:
>
>
>
>
>
>
>
> > Hi!
>
> > I've had not feedback from my post below. Is something wrong with it?
>
> > Kind regards,
>
> > Emmanuel
>
> > -----Message d'origine-----
> > 717e3f
> >http://groups.google.com/group/zotonic-developers/browse_thread/threa...
Andreas Stenius
https://github.com/kaos/zotonic/commit/769e1999afaeb029fcec205d8b80df02871a8e20
(oct 28, master branch)
with a comment of "more to follow"...
The change, as far as I can see from a quick glance, is to give sites
a full minute to start; and a few more changes...
Perhaps back-port this to 0.7.x?
//Andreas
2012/2/12 Arjan Scherpenisse <ar...@scherpenisse.net>:
> Hi Emmanuel,
>
> thanks for your detailed report. There's nothing wrong with it, however
> it might have lingered in mailing list queue for a while (we review all
> messages first time somebody sends something, to prevent spam).
>
> The issue that sometimes a site takes too long to startup is indeed very
> annoying and leads to strange behaviour.
>
> I am tempted to commit your solution (changing z_supervisor to allow a
> longer startup time for childs) but I'd first like some feedback from
> the other developers (Marc, Andreas, Maas?)
>
> One more thought: choosing 'infinity' means you trust all sites (and
> modules!) not to do anything stupid in their startup code: the whole
> system may fail to start up if one site decides to block.
>
> Cheers,
> Arjan
>
> On 02/11/2012 09:53 PM, Emmanuel Boutin wrote:
>> Hi!
>>
>> I've had not feedback from my post below. Is something wrong with it?
>>
>> Kind regards,
>>
>> Emmanuel
>>
>> -----Message d'origine-----
>> De : eboutin [mailto:emmanue...@free.fr]
>> Envoyé : samedi 4 février 2012 14:52
>> À : Zotonic developers
>> Et voilà! Zotonic started for the first time on our dedicated server
Arjan Scherpenisse
I'm actually never experiencing this startup annoyance anymore, but that
is probably because I only run master :-)
If no further objections I'll backport it and churn out a release
somewhere this week.
grt Arjan
>>> Envoy� : samedi 4 f�vrier 2012 14:52
>>> � : Zotonic developers
>>> Et voil�! Zotonic started for the first time on our dedicated server
Arjan Scherpenisse
it is part of a bigger change (module dependencies and changing the
module startup sequence) that is too hard to merge properly.
I'm afraid it cannot be backported to the 0.7 series.
Emmanuel, you are suggested to run on the git master while we are
preparing the next stable 0.8 release ("real soon now!")
Arjan
eboutin
Thanks for following this up.
For the moment we're happy with our locally hacked version.
We'll be glad to switch to the next stable 0.8 release real soon ;-)
Regards,
Emmanuel
On 16 fév, 11:13, Arjan Scherpenisse <ar...@scherpenisse.net> wrote:
> OK I looked into merging Marc's "module stability fix" (769e1999afa) but
> it is part of a bigger change (module dependencies and changing the
> module startup sequence) that is too hard to merge properly.
> I'm afraid it cannot be backported to the 0.7 series.
>
> Emmanuel, you are suggested to run on the git master while we are
> preparing the next stable 0.8 release ("real soon now!")
>
> Arjan
>
> On 02/13/2012 02:27 PM, Arjan Scherpenisse wrote:
>
>
>
>
>
>
>
> > That sounds like a good idea..
>
> > I'm actually never experiencing this startup annoyance anymore, but that
> > is probably because I only run master :-)
>
> > If no further objections I'll backport it and churn out a release
> > somewhere this week.
>
> > grt Arjan
>
> > On 02/13/2012 01:26 PM, Andreas Stenius wrote:
> >> Marc has addressed this in
> >>>> 717e3f
> >>>>http://groups.google.com/group/zotonic-developers/browse_thread/threa...