xenserver / buildroot

Package buildroot for xen-api and related packages
44 stars 29 forks source link

Ubuntu (Trusty): 'server-init' is still pending long after restart #601

Open kevteljeur opened 9 years ago

kevteljeur commented 9 years ago

After restarting the server, the following can be observed:

xe task-list
                uuid ( RO): 709afe91-5f98-aecb-3d1e-030160c20496
          name-label ( RO): server_init
    name-description ( RO): 
              status ( RO): pending
            progress ( RO): 0.000

Possibly relevant log entries:

Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [XAPI SERVER STARTING]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task XAPI SERVER STARTING D:2715b1c3cf7e created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Parsing inventory file]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Parsing inventory file D:62af84ddd007 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Setting stunnel timeout]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Setting stunnel timeout D:6a96edd5957b created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Initialising local database]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Initialising local database D:dcd9d51d5171 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Loading DHCP leases]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Loading DHCP leases D:c7c9579fff7d created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Reading pool secret]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Reading pool secret D:3c1baa0dd596 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Logging xapi version info]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Logging xapi version info D:4e648d41d088 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Setting signal handlers]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Setting signal handlers D:c5d3161b5820 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Initialising random number generator]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Initialising random number generator D:0f80b18ed1f7 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Running startup check]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Running startup check D:91a6de3eb5d9 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Registering SMAPIv1 plugins]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Registering SMAPIv1 plugins D:a45edc7367b9 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Starting SMAPIv1 proxies]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Starting SMAPIv1 proxies D:6742de04ac0f created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Initialising SM state]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Initialising SM state D:c38bdbe1615e created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Starting SM internal event service]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Starting SM internal event service D:a741fd4601a1 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Starting SM service]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Starting SM service D:d83e7c5dcb5d created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Starting SM xapi event service]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Starting SM xapi event service D:539ec40fbb79 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Registering http handlers]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Registering http handlers D:0604d3c46967 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Registering master-only http handlers]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Registering master-only http handlers D:a1b44197d520 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Listening unix socket]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Listening unix socket D:1b54c8a2caaf created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [starting thread Metadata VDI liveness monitor]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Checking HA configuration]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Checking HA configuration D:e7d56b88a450 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Checking for non-HA redo-log]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Checking for non-HA redo-log D:9ff3ffd006e5 created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [Setup DB configuration]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task Setup DB configuration D:c03e4bc2aaaf created by task D:708f34f50b32
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [starting up database engine]
Jan 14 09:41:41 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task starting up database engine D:f400ddf158e0 created by task D:708f34f50b32
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [hi-level database upgrade]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task hi-level database upgrade D:41d6bbf23cb9 created by task D:708f34f50b32
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [bringing up management interface]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|dummytaskhelper] task bringing up management interface D:67ebeb9cda6b created by task D:708f34f50b32
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [starting thread Starting periodic scheduler]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init D:708f34f50b32|startup] task [starting thread Remote requests]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Checking emergency network reset]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Checking emergency network reset D:98912b369c5f created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Upgrade bonds to Boston]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Upgrade bonds to Boston D:71bfe7a09749 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Initialise monitor configuration]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Initialise monitor configuration D:590dcc9d425c created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Initialising licensing]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Initialising licensing D:b888265123f4 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [message_hook_thread]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task message_hook_thread D:6da739bcd56a created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [starting thread heartbeat thread]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [resynchronising HA state]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task resynchronising HA state D:c1e7a6b33508 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [starting thread pool db backup]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [starting thread monitor_dbcalls]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [touching ready file]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task touching ready file D:e15332a29061 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Performing no-other-masters check]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Performing no-other-masters check D:6cd21dc25712 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Registering periodic functions]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Registering periodic functions D:791e7a93ec8d created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [executing startup scripts]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task executing startup scripts D:dacb6eb95d6c created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [considering executing on-master-start script]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task considering executing on-master-start script D:312a2363d9a6 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [creating networks]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task creating networks D:efc099e7c365 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [updating the vswitch controller]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task updating the vswitch controller D:43da90c2b8d3 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [Best-effort bring up of physical NICs]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task Best-effort bring up of physical NICs D:a2d650187f73 created by task R:71f1526b667a
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|startup] task [initialising storage]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|server_init R:71f1526b667a|dummytaskhelper] task initialising storage D:5d1408133797 created by task R:71f1526b667a

This is intermittent, but I suspect that it may be preventing other tasks from being successfully completed.

jonludlam commented 9 years ago

try 'xe task-list params=all' - there may be some extra info there. Additionally, grep for 'thread_zero' in syslog and see what the last few log lines mention.

kevteljeur commented 9 years ago
xe task-list params=all
                  uuid ( RO): 709afe91-5f98-aecb-3d1e-030160c20496
            name-label ( RO): server_init
      name-description ( RO): 
            subtask_of ( RO): <not in database>
              subtasks ( RO): 
           resident-on ( RO): 9c661c2d-dc93-4a72-9214-9b724a333dbc
                status ( RO): pending
              progress ( RO): 0.000
                  type ( RO): <none/>
                result ( RO): 
               created ( RO): 20150114T08:41:45Z
              finished ( RO): 19700101T00:00:00Z
            error_info ( RO): 
    allowed_operations ( RO): 
          other-config (MRW): startup_operation: initialising storage

And:

Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Currently-attached SRs: [  ]
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:b417f286-a45b-4260-6960-bc9f6787d3eb currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:9ec85e77-b6cc-eaff-3c77-0e7f1fd91e5e currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:9c87113a-1261-46db-3a48-9ba7946bd8cd currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:9081f9bb-db06-722e-f395-700f3c8736cc currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:81c4eff3-ed37-c884-595f-dfc169b122d8 currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:4cba0c0c-8bde-5654-ac89-f56a6a16782d currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:2648ad70-2599-e55a-9637-4d82e366e9f3 currently_attached <- false
Jan 14 09:41:45 ns206094 xapi: [debug|ns206094.ip-94-23-42.eu|0 thread_zero|creating storage D:27f9e0eac669|storage_access] Setting PBD OpaqueRef:14ded951-aaa0-8825-fc8f-e159d430527c currently_attached <- false
jonludlam commented 9 years ago

What does 'message-cli diag' say?

kevteljeur commented 9 years ago
$ message-cli diagnostics
Switch uptime: 83883744 ms
Permanent queues
  org.xen.xcp.memory next update expected: 1937 ms
  org.xen.xcp.storage next update expected: 1938 ms
  org.xen.xcp.xenops.classic next update expected: 1938 ms
  org.xen.xcp.networkd next update expected: 1938 ms
  org.xen.xcp.storage.ezlvm next update expected: 1938 ms
  org.xen.xcp.storage.iso next update expected: None
    0:  from: xapi%3A2456  age: 83877359 ms
      {\"method\": \"Query.query\", \"params\": [{\"dbg\": \"creating storag
        reply_to: xapi%3A2456
  org.xen.xcp.xenops.xenlight next update expected: 1937 ms
  org.xen.xcp.storage.ffs next update expected: 1938 ms
Transient queues
  xapi%3A2456 next update expected: 1938 ms

Hope that helps!

Kevin