Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
kevteljeur opened this issue Jan 14, 2015 · 4 comments
Open

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

kevteljeur opened this issue Jan 14, 2015 · 4 comments
Labels
deb

Comments

@kevteljeur
Copy link

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
Copy link
Collaborator

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
Copy link
Author 

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
Copy link
Collaborator

What does 'message-cli diag' say?

@kevteljeur
Copy link
Author 

$ 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

@euanh euanh added the deb label Apr 23, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
deb
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jonludlam @kevteljeur @euanh