Xen devel - Dec 2011 - [PATCH 0 of 4 V2] oxenstored fixes -- fixes recent pvops kernel hang

Currently PVHVM Linux guests after ddacf5ef684a "xen/pv-on-hvm kexec:
add xs_reset_watches to shutdown watches from old kernel" hang when
run against oxenstored because it does not handle the unknown
XS_RESET_WATCHES operation and does not reply.

The symptom of this issue is a hang during boot at this point:
    cpu 1 spinlock event irq 70
    CPU 1 irqstacks, hard=dec94000 soft=dec96000
    Booting Node   0, Processors  #1
    smpboot cpu 1: start_ip = 99000
    Initializing CPU#1
    installing Xen timer for CPU 1
    Brought up 2 CPUs
    Total of 2 processors activated (9625.99 BogoMIPS).
    NET: Registered protocol family 16
    <HANG>

This series makes oxenstored handle unknown operations by returning an
error indicating that the operation is unknown. I have not actually
implemented support for XS_RESET_WATCHES.

I also include a patch which I''ve been using for some time to enable
the use of oxenstored in preference to C xenstored when available.

Also included are two (more) little cleanup patches

Changes since v1: 

* First two cleanup patches applied already
* Two more cleanup patches added
* Fixed warning in "handle unknown operations by returning an error to
  the client"

# HG changeset patch
# User Ian Campbell <ian.campbell@citrix.com>
# Date 1323792488 0
# Node ID 06c6ba6641640a2fa0ef6f998405f5f7c43bb258
# Parent  74ab4d0c8ebac8d9d344dab3bf440f510d23377d
oxenstored: handle unknown operations by returning an error to the client

Previous an unknown operation would be decoded as a Not_found exception which
would bubble all the way up to the try ... with surrounding the call to
main_loop where it would be logged and ignored.

This would leave the guest hanging waiting for a response to the invalid
request.

Instead introduce a specific "Invalid" operation. Higher level
functionality,
such as Process.process_packet, already handles operations which are not
understood with an error reply due to the final wildcard entry in
Process.function_of_type but explicitly handle Invalid this way to make it
clear what is going on.

Signed-off-by: Ian Campbell <ian.campbell@citrix.com>

diff -r 74ab4d0c8eba -r 06c6ba664164 tools/ocaml/libs/xb/op.ml
--- a/tools/ocaml/libs/xb/op.ml	Tue Dec 13 16:07:40 2011 +0000
+++ b/tools/ocaml/libs/xb/op.ml	Tue Dec 13 16:08:08 2011 +0000
@@ -19,8 +19,7 @@ type operation = Debug | Directory | Rea
                  Transaction_end | Introduce | Release |
                  Getdomainpath | Write | Mkdir | Rm |
                  Setperms | Watchevent | Error | Isintroduced |
-                 Resume | Set_target
-               | Restrict 
+                 Resume | Set_target | Restrict | Invalid
 
 let operation_c_mapping  	[| Debug; Directory; Read; Getperms;
@@ -41,7 +40,7 @@ let array_search el a  let of_cval i  	if i >= 0 &&
i < size
 	then operation_c_mapping.(i)
-	else raise Not_found
+	else Invalid
 
 let to_cval op  	array_search op operation_c_mapping
@@ -69,3 +68,4 @@ let to_string ty  	| Resume		-> "RESUME"
 	| Set_target		-> "SET_TARGET"
 	| Restrict		-> "RESTRICT"
+	| Invalid		-> "INVALID"
diff -r 74ab4d0c8eba -r 06c6ba664164 tools/ocaml/libs/xb/xb.mli
--- a/tools/ocaml/libs/xb/xb.mli	Tue Dec 13 16:07:40 2011 +0000
+++ b/tools/ocaml/libs/xb/xb.mli	Tue Dec 13 16:08:08 2011 +0000
@@ -23,6 +23,7 @@ module Op :
       | Resume
       | Set_target
       | Restrict
+      | Invalid (* Not a valid wire operation *)
     val operation_c_mapping : operation array
     val size : int
     val array_search : ''a -> ''a array -> int
diff -r 74ab4d0c8eba -r 06c6ba664164 tools/ocaml/xenstored/logging.ml
--- a/tools/ocaml/xenstored/logging.ml	Tue Dec 13 16:07:40 2011 +0000
+++ b/tools/ocaml/xenstored/logging.ml	Tue Dec 13 16:08:08 2011 +0000
@@ -182,6 +182,7 @@ let string_of_access_type = function
 
 	| Xenbus.Xb.Op.Error             -> "error    "
 	| Xenbus.Xb.Op.Watchevent        -> "w event  "
+	| Xenbus.Xb.Op.Invalid           -> "invalid  "
 	(*
 	| x                       -> Xenbus.Xb.Op.to_string x
 	*)
diff -r 74ab4d0c8eba -r 06c6ba664164 tools/ocaml/xenstored/process.ml
--- a/tools/ocaml/xenstored/process.ml	Tue Dec 13 16:07:40 2011 +0000
+++ b/tools/ocaml/xenstored/process.ml	Tue Dec 13 16:08:08 2011 +0000
@@ -324,7 +324,8 @@ let function_of_type ty  	| Xenbus.Xb.Op.Resume           
-> reply_ack do_resume
 	| Xenbus.Xb.Op.Set_target        -> reply_ack do_set_target
 	| Xenbus.Xb.Op.Restrict          -> reply_ack do_restrict
-	| _                       -> reply_ack do_error
+	| Xenbus.Xb.Op.Invalid           -> reply_ack do_error
+	| _                              -> reply_ack do_error
 
 let input_handle_error ~cons ~doms ~fct ~ty ~con ~t ~rid ~data  	let
reply_error e diff -r 74ab4d0c8eba -r 06c6ba664164
tools/ocaml/xenstored/xenstored.ml
--- a/tools/ocaml/xenstored/xenstored.ml	Tue Dec 13 16:07:40 2011 +0000
+++ b/tools/ocaml/xenstored/xenstored.ml	Tue Dec 13 16:08:08 2011 +0000
@@ -43,9 +43,7 @@ let process_connection_fds store cons do
 			debug "closing socket connection"
 		in
 	let process_fdset_with fds fct -		List.iter (fun fd ->
-		           try try_fct fct (Connections.find cons fd)
-		           with Not_found -> ()) fds
+		List.iter (fun fd -> try_fct fct (Connections.find cons fd)) fds
 	in
 	process_fdset_with rset Process.do_input;
 	process_fdset_with wset Process.do_output

# HG changeset patch
# User Ian Campbell <ian.campbell@citrix.com>
# Date 1323792507 0
# Node ID f4586d1a539c869e31fadc8b3c3223bd118b37fc
# Parent  06c6ba6641640a2fa0ef6f998405f5f7c43bb258
Linux/xencommons: Use oxenstored by default when available

oxenstored is an ocaml implementation of the xenstore daemon. It is faster,
more scalable and more reliable than the C xenstored.

In particular the transaction model in oxenstored does not involve taking a
complete copy of the database and aborting on any (even non-conflicting) other
change.

There is a paper on the design and implementation of oxenstored at
http://gazagnaire.org/pub/GH09.pdf which includes a performance evaluation and
comparison with the C daemon etc.

Signed-off-by: Ian Campbell <ian.campbell@citrix.com>

diff -r 06c6ba664164 -r f4586d1a539c
tools/hotplug/Linux/init.d/sysconfig.xencommons
--- a/tools/hotplug/Linux/init.d/sysconfig.xencommons	Tue Dec 13 16:08:08 2011
+0000
+++ b/tools/hotplug/Linux/init.d/sysconfig.xencommons	Tue Dec 13 16:08:27 2011
+0000
@@ -1,6 +1,9 @@
 # Log xenconsoled messages (cf xl dmesg)
 XENCONSOLED_TRACE=guest
 
+# Select xenstored implementation
+#XENSTORED=[oxenstored|xenstored]
+
 # Log xenstored messages
 #XENSTORED_TRACE=[yes|on|1]
 
diff -r 06c6ba664164 -r f4586d1a539c tools/hotplug/Linux/init.d/xencommons
--- a/tools/hotplug/Linux/init.d/xencommons	Tue Dec 13 16:08:08 2011 +0000
+++ b/tools/hotplug/Linux/init.d/xencommons	Tue Dec 13 16:08:27 2011 +0000
@@ -70,8 +70,19 @@ do_start () {
 		rm -f "$XENSTORED_ROOTDIR"/tdb* &>/dev/null
 		test -z "$XENSTORED_TRACE" || XENSTORED_ARGS=" -T
/var/log/xen/xenstored-trace.log"
 
-		echo -n Starting xenstored...
-		xenstored --pid-file=/var/run/xenstored.pid $XENSTORED_ARGS
+		if [ -n "$XENSTORED" ] ; then
+		    echo -n Starting $XENSTORED...
+		    $XENSTORED --pid-file /var/run/xenstored.pid $XENSTORED_ARGS
+		elif [ -x /usr/sbin/oxenstored ] ; then
+		    echo -n Starting oxenstored...
+		    /usr/sbin/oxenstored --pid-file /var/run/xenstored.pid $XENSTORED_ARGS
+		elif [ -x /usr/sbin/xenstored ] ; then
+		    echo -n Starting C xenstored...
+		    /usr/sbin/xenstored --pid-file /var/run/xenstored.pid $XENSTORED_ARGS
+		else
+		    echo "No xenstored found"
+		    exit 1
+		fi
 
 		# Wait for xenstored to actually come up, timing out after 30 seconds
                 while [ $time -lt $timeout ] && ! `xenstore-read -s /
>/dev/null 2>&1` ; do

# HG changeset patch
# User Ian Campbell <ian.campbell@citrix.com>
# Date 1323792537 0
# Node ID fd321c47d4b8e7095758e008ad3801e5d16461a7
# Parent  f4586d1a539c869e31fadc8b3c3223bd118b37fc
oxenstored: install configuration file

First though:
  - Move it to /etc/xen/oxenstored.conf.
  - Use /var/run/xenstored.pid as default pid file
  - Disable test-eagain "Randomly failed a transaction with EAGAIN. Used
for
    testing Xs user". Doesn''t sound fun by default...

Signed-off-by: Ian Campbell <ian.campbell@citrix.com>

diff -r f4586d1a539c -r fd321c47d4b8 tools/ocaml/xenstored/Makefile
--- a/tools/ocaml/xenstored/Makefile	Tue Dec 13 16:08:27 2011 +0000
+++ b/tools/ocaml/xenstored/Makefile	Tue Dec 13 16:08:57 2011 +0000
@@ -52,5 +52,7 @@ bins: $(PROGRAMS)
 install: all
 	$(INSTALL_DIR) $(DESTDIR)$(SBINDIR)
 	$(INSTALL_PROG) oxenstored $(DESTDIR)$(SBINDIR)
+	$(INSTALL_DIR) $(DESTDIR)$(XEN_CONFIG_DIR)
+	$(INSTALL_DATA) oxenstored.conf $(DESTDIR)$(XEN_CONFIG_DIR)
 
 include $(OCAML_TOPLEVEL)/Makefile.rules
diff -r f4586d1a539c -r fd321c47d4b8 tools/ocaml/xenstored/define.ml
--- a/tools/ocaml/xenstored/define.ml	Tue Dec 13 16:08:27 2011 +0000
+++ b/tools/ocaml/xenstored/define.ml	Tue Dec 13 16:08:57 2011 +0000
@@ -23,7 +23,7 @@ let xenstored_proc_port = "/proc/xen/xsd
 let xs_daemon_socket = "/var/run/xenstored/socket"
 let xs_daemon_socket_ro = "/var/run/xenstored/socket_ro"
 
-let default_config_dir = "/etc/xensource"
+let default_config_dir = "/etc/xen"
 
 let maxwatch = ref (50)
 let maxtransaction = ref (20)
diff -r f4586d1a539c -r fd321c47d4b8 tools/ocaml/xenstored/oxenstored.conf
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/tools/ocaml/xenstored/oxenstored.conf	Tue Dec 13 16:08:57 2011 +0000
@@ -0,0 +1,35 @@
+# default xenstored config
+
+# Where the pid file is stored
+pid-file = /var/run/xenstored.pid
+
+# Randomly failed a transaction with EAGAIN. Used for testing Xs user
+test-eagain = false
+
+# Activate transaction merge support
+merge-activate = true
+
+# Activate node permission system
+perms-activate = true
+
+# Activate quota
+quota-activate = true
+quota-maxentity = 1000
+quota-maxsize = 2048
+quota-maxwatch = 100
+quota-transaction = 10
+
+# Activate filed base backend
+persistant = false
+
+# Xenstored logs
+# xenstored-log-file = /var/log/xenstored.log
+# xenstored-log-level = null
+# xenstored-log-nb-files = 10
+
+# Xenstored access logs
+# access-log-file = /var/log/xenstored-access.log
+# access-log-nb-lines = 13215
+# acesss-log-nb-chars = 180
+# access-log-special-ops = false
+
diff -r f4586d1a539c -r fd321c47d4b8 tools/ocaml/xenstored/xenstored.conf
--- a/tools/ocaml/xenstored/xenstored.conf	Tue Dec 13 16:08:27 2011 +0000
+++ /dev/null	Thu Jan 01 00:00:00 1970 +0000
@@ -1,35 +0,0 @@
-# default xenstored config
-
-# Where the pid file is stored
-pid-file = /var/run/xensource/xenstored.pid
-
-# Randomly failed a transaction with EAGAIN. Used for testing Xs user
-test-eagain = true
-
-# Activate transaction merge support
-merge-activate = true
-
-# Activate node permission system
-perms-activate = true
-
-# Activate quota
-quota-activate = true
-quota-maxentity = 1000
-quota-maxsize = 2048
-quota-maxwatch = 100
-quota-transaction = 10
-
-# Activate filed base backend
-persistant = false
-
-# Xenstored logs
-# xenstored-log-file = /var/log/xenstored.log
-# xenstored-log-level = null
-# xenstored-log-nb-files = 10
-
-# Xenstored access logs
-# access-log-file = /var/log/xenstored-access.log
-# access-log-nb-lines = 13215
-# acesss-log-nb-chars = 180
-# access-log-special-ops = false
-
diff -r f4586d1a539c -r fd321c47d4b8 tools/ocaml/xenstored/xenstored.ml
--- a/tools/ocaml/xenstored/xenstored.ml	Tue Dec 13 16:08:27 2011 +0000
+++ b/tools/ocaml/xenstored/xenstored.ml	Tue Dec 13 16:08:57 2011 +0000
@@ -71,7 +71,7 @@ let sighup_handler _  let config_filename cf  	match
cf.config_file with
 	| Some name -> name
-	| None      -> Define.default_config_dir ^ "/xenstored.conf"
+	| None      -> Define.default_config_dir ^ "/oxenstored.conf"
 
 let default_pidfile = "/var/run/xenstored.pid"

# HG changeset patch
# User Ian Campbell <ian.campbell@citrix.com>
# Date 1323792620 0
# Node ID f2e14742b2a2c1f40bc36063a1485b4072865fd1
# Parent  fd321c47d4b8e7095758e008ad3801e5d16461a7
oxenstored: Always log something at start of day (if logging enabled at all)

Otherwise at the default level we rarely log anything at all.

A completely empty log file is a good sign, but only if you know you are
looking in the right place...

Signed-off-by: Ian Campbell <ian.campbell@citrix.com>

diff -r fd321c47d4b8 -r f2e14742b2a2 tools/ocaml/xenstored/logging.ml
--- a/tools/ocaml/xenstored/logging.ml	Tue Dec 13 16:08:57 2011 +0000
+++ b/tools/ocaml/xenstored/logging.ml	Tue Dec 13 16:10:20 2011 +0000
@@ -117,6 +117,9 @@ let init_xenstored_log ()  			make_logger 
 				!xenstored_log_file !xenstored_log_nb_files !xenstored_log_nb_lines
 				!xenstored_log_nb_chars ignore in
+		let date = string_of_date() in
+		logger.write ("[%s|%5s|%s] Xen Storage Daemon, version %d.%d") date
"" "startup"
+		  Define.xenstored_major Define.xenstored_minor;
 		xenstored_logger := Some logger
 
 let xenstored_logging level key (fmt: (_,_,_,_) format4) diff -r fd321c47d4b8
-r f2e14742b2a2 tools/ocaml/xenstored/xenstored.ml
--- a/tools/ocaml/xenstored/xenstored.ml	Tue Dec 13 16:08:57 2011 +0000
+++ b/tools/ocaml/xenstored/xenstored.ml	Tue Dec 13 16:10:20 2011 +0000
@@ -284,9 +284,6 @@ let _  		Logging.init_access_log post_rotate
 	end;
 
-	info "Xen Storage Daemon, version %d.%d"
-	     Define.xenstored_major Define.xenstored_minor;
-
 	let spec_fds  		(match rw_sock with None -> [] | Some x -> [ x ]) @
 		(match ro_sock with None -> [] | Some x -> [ x ]) @

Ian,

On Tue, 2011-12-13 at 16:12 +0000, Ian Campbell wrote:
> I also include a patch which I''ve been using for some time to
enable
> the use of oxenstored in preference to C xenstored when available.
Can you also arrange for the test system to
collect /etc/xen/oxenstored.conf, /var/log/xenstored.conf*
and /var/log/xenstored-access.log* please.

Ian.

Ian Campbell writes ("Re: [Xen-devel] [PATCH 0 of 4 V2] oxenstored fixes --
fixes recent pvops kernel hang"):
> On Tue, 2011-12-13 at 16:12 +0000, Ian Campbell wrote:
> > I also include a patch which I''ve been using for some time to
enable
> > the use of oxenstored in preference to C xenstored when available.
> 
> Can you also arrange for the test system to
> collect /etc/xen/oxenstored.conf, /var/log/xenstored.conf*
> and /var/log/xenstored-access.log* please.
I hadn''t spotted these filenames in the source for oxenstored.
"/var/log/xenstored.conf*" ?!  omg wtf bbq

Surely these should all be in /var/log/xen.

But I have added them to the list of files to be collected.

Ian.

On Thu, 2011-12-15 at 14:44 +0000, Ian Jackson wrote:
> Ian Campbell writes ("Re: [Xen-devel] [PATCH 0 of 4 V2] oxenstored
fixes -- fixes recent pvops kernel hang"):
> > On Tue, 2011-12-13 at 16:12 +0000, Ian Campbell wrote:
> > > I also include a patch which I''ve been using for some
time to enable
> > > the use of oxenstored in preference to C xenstored when
available.
> > 
> > Can you also arrange for the test system to
> > collect /etc/xen/oxenstored.conf, /var/log/xenstored.conf*
> > and /var/log/xenstored-access.log* please.
> 
> I hadn''t spotted these filenames in the source for oxenstored.
> "/var/log/xenstored.conf*" ?!  omg wtf bbq
Sorry, that''s my typo, I meant /var/log/xenstored.log*. The .conf name
under /etc/xen is correct.
> Surely these should all be in /var/log/xen.
Could move them I guess. I''d like to hear from Jon and the XCP chaps
though. Patch would be the following, I think.

Ian.

diff -r 0ddea44c2a7f tools/ocaml/xenstored/logging.ml
--- a/tools/ocaml/xenstored/logging.ml	Thu Dec 15 11:52:48 2011 +0000
+++ b/tools/ocaml/xenstored/logging.ml	Thu Dec 15 15:35:39 2011 +0000
@@ -104,7 +104,7 @@ let string_of_date ()  		tm.Unix.tm_hour tm.Unix.tm_min
tm.Unix.tm_sec
 		(int_of_float (1000.0 *. msec))
 
-let xenstored_log_file = ref "/var/log/xenstored.log"
+let xenstored_log_file = ref "/var/log/xen/xenstored.log"
 let xenstored_log_level = ref Warn
 let xenstored_log_nb_files = ref 10
 let xenstored_log_nb_lines = ref 13215
@@ -200,7 +200,7 @@ let sanitize_data data  	String.escaped data
 
 let activate_access_log = ref true
-let access_log_file = ref "/var/log/xenstored-access.log"
+let access_log_file = ref "/var/log/xen/xenstored-access.log"
 let access_log_nb_files = ref 20
 let access_log_nb_lines = ref 13215
 let access_log_nb_chars = ref 180
diff -r 0ddea44c2a7f tools/ocaml/xenstored/oxenstored.conf
--- a/tools/ocaml/xenstored/oxenstored.conf	Thu Dec 15 11:52:48 2011 +0000
+++ b/tools/ocaml/xenstored/oxenstored.conf	Thu Dec 15 15:35:39 2011 +0000
@@ -23,12 +23,12 @@ quota-transaction = 10
 persistant = false
 
 # Xenstored logs
-# xenstored-log-file = /var/log/xenstored.log
+# xenstored-log-file = /var/log/xen/xenstored.log
 # xenstored-log-level = null
 # xenstored-log-nb-files = 10
 
 # Xenstored access logs
-# access-log-file = /var/log/xenstored-access.log
+# access-log-file = /var/log/xen/xenstored-access.log
 # access-log-nb-lines = 13215
 # acesss-log-nb-chars = 180
 # access-log-special-ops = false

Ian Campbell writes ("[Xen-devel] [PATCH 2 of 4 V2] Linux/xencommons: Use
oxenstored by default when available"):
> Linux/xencommons: Use oxenstored by default when available
I''ve applied #1, #3, and #4.  I''ll wait with #2 until my test
system
gets a pass and push on the change to collect the oxenstored logs.

Ian.

On Thu, 2011-12-15 at 16:54 +0000, Ian Jackson wrote:
> Ian Campbell writes ("[Xen-devel] [PATCH 2 of 4 V2] Linux/xencommons:
Use oxenstored by default when available"):
> > Linux/xencommons: Use oxenstored by default when available
> 
> I''ve applied #1, #3, and #4.  I''ll wait with #2 until my
test system
> gets a pass and push on the change to collect the oxenstored logs.
Sounds good. Thanks.

Ian.

On Thu, 2011-12-15 at 16:56 +0000, Ian Campbell wrote:
> On Thu, 2011-12-15 at 16:54 +0000, Ian Jackson wrote:
> > Ian Campbell writes ("[Xen-devel] [PATCH 2 of 4 V2]
Linux/xencommons: Use oxenstored by default when available"):
> > > Linux/xencommons: Use oxenstored by default when available
> > 
> > I''ve applied #1, #3, and #4.  I''ll wait with #2
until my test system
> > gets a pass and push on the change to collect the oxenstored logs.
> 
> Sounds good. Thanks.
But did you see my response re: /var/log/xenstored.conf
vs /var/log/xenstored.log in
<1323963349.20077.494.camel@zakaz.uk.xensource.com> ?

Ian.

Ian Campbell writes ("Re: [Xen-devel] [PATCH 2 of 4 V2] Linux/xencommons:
Use oxenstored by default when available"):
> On Thu, 2011-12-15 at 16:56 +0000, Ian Campbell wrote:
> > On Thu, 2011-12-15 at 16:54 +0000, Ian Jackson wrote:
> > > I''ve applied #1, #3, and #4.  I''ll wait with #2
until my test system
> > > gets a pass and push on the change to collect the oxenstored
logs.
> > 
> > Sounds good. Thanks.
> 
> But did you see my response re: /var/log/xenstored.conf
> vs /var/log/xenstored.log in
> <1323963349.20077.494.camel@zakaz.uk.xensource.com> ?
Yes :-).

Ian.

Ian Campbell writes ("[Xen-devel] [PATCH 2 of 4 V2] Linux/xencommons: Use
oxenstored by default when available"):
> Linux/xencommons: Use oxenstored by default when available
Committed-by: Ian Jackson <ian.jackson@eu.citrix.com>