Here are the steps in from the controller csit job for restarting ODL (Restart Odl With Tell Based False). 
 
1. kill -9 on karaf pid ( 'ps axf | grep org.apache.karaf | grep -v grep | awk '{print "kill -9 " $1}' | sh' )
2. Verify karaf is not running
3. Set Tell Based to False in config file
4. Copy karaf logs to /tmp (mkdir -p '/tmp' && rm -vrf '/tmp/log' && mv -vf '/tmp/karaf-0.8.3-SNAPSHOT/data/log' '/tmp/')
5. Clean the following directories

1. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/tmp/
2. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/data/
3. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/cache/
4. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/snapshots/
5. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/journal/
6. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/etc/opendaylight/current/
7. rm -rf /tmp/karaf-0.8.3-SNAPSHOT/etc/host.key

6. Copy logs back to new snapshot dir, as below: # mkdir -p '/tmp/karaf-0.8.3-SNAPSHOT/data' && rm -vrf '/tmp/karaf-0.8.3-SNAPSHOT/log' && mv -vf '/tmp/log' '/tmp/karaf-0.8.3-SNAPSHOT/data/

Tom, 

I'll have to get this to fail again in CSIT, and will share the link to the run, which will have the karaf thread dumps you asked for to help debug this issue.

If it is due to karaf taking 7 minutes to re-install features, it does hit the disk a lot so I wonder if it's an intermittent issue with disk performance in the jenkins environment.

Would need a thread dump when this issue occurs.

Need to find a reliable way to reproduce this issue.

kill -3 for jvm pid will go to stdout, karaf.out

Did CSIT start karaf twice?

vorburger, tpantelis, vpickard,

which part of the karaf log in the description is "weird" and maybe a problem in csit. I will investigate
and update this jira.

I don't have the full context of what is going on here or what this CSIT does, but the first thing that pops out at me is that what is shown in the description of this issue above looks like two Karaf instances started, one at 3:43:47 and then another at 3:50:48 - not one karaf took just a little over 7 minutes to start up. (Look closely, and compare it with the output of when start ODL locally - you'll find "half" of what is shown above.)

Does this observation help you?

yes there should only be one set. It's as if karaf was started then killed and then started again. 

We don't have the accompanying csit (e.g. robot) logs for the karaf log in the description, but I was hoping
it was what we'd see when I tracked down a recent example of CONTROLLER-1768. It's not.

vpickard, hoping we can get another example of this karaf.log to go with the robot logs. I'll keep looking
myself.

From the logs, it is observed that there are messages of JoinSeedNodeProcess which fails with retries before all instances of Karaf Restart - org.apache.karaf.main.Main launch

The order of seed-nodes must be uniform across all ODL nodes and availability of first of seed-nodes  is pre-requisite. We can check if at least first condition is satisfied in the target deployment. 

tpantelis

One clarification

We do not have Quarantine-based suicide and restart (QuarantinedMonitorActor) of ODL process in master - is my understanding correct ?

Not seeing any such symptoms on the logs unless QuarantinedMonitorActor had been refactored into some other name retaining suicidal + restart behavior 

. 

The quarantined/restart mechanism is still there. But how is what you stated above relevant for this JIRA? This is about what looks to be a 7 min gap during karaf startup and not related to our clustering.

I saw something similiar in another run, but in this case, ODL/karaf appears to just hang, i.e., no logs after the first initial startup sequence.

Sandbox link:

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/181/controller-csit-3node-clustering-vpickard-all-oxygen/23/

Final logs in odl3 karaf log:

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/181/controller-csit-3node-clustering-vpickard-all-oxygen/23/odl3_karaf.log.gz

Jul 04, 2018 12:43:35 PM org.apache.karaf.main.Main launch
INFO: Installing and starting initial bundles
Jul 04, 2018 12:43:35 PM org.apache.karaf.main.Main launch
INFO: All initial bundles installed and set to start
Jul 04, 2018 12:43:35 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /tmp/karaf-0.8.3-SNAPSHOT/lock
Jul 04, 2018 12:43:35 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 04, 2018 12:43:35 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100

Normal startups look something like this:

ul 04, 2018 12:24:53 PM org.apache.karaf.main.Main launch
INFO: Installing and starting initial bundles
Jul 04, 2018 12:24:53 PM org.apache.karaf.main.Main launch
INFO: All initial bundles installed and set to start
Jul 04, 2018 12:24:54 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /tmp/karaf-0.8.3-SNAPSHOT/lock
Jul 04, 2018 12:24:54 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 04, 2018 12:24:54 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100
2018-07-04T12:25:00,969 | INFO | pool-1-thread-2 | FeaturesServiceImpl | 8 - org.apache.karaf.features.core - 4.1.5 | Adding features: odl-integration-compatible-with-all/[0.8.3.SNAPSHOT,0.8.3.SNAPSHOT], odl-jolokia/[1.10.3.SNAPSHOT,1.10.3.SNAPSHOT], odl-restconf/[1.7.3.SNAPSHOT,1.7.3.SNAPSHOT], odl-clustering-test-app/[1.7.3.SNAPSHOT,1.7.3.SNAPSHOT], 42ecb7fe-aed1-4fa7-930f-d13bd83ea61a/[0,0.0.0]
2018-07-04T12:25:01,236 | INFO | features-1-thread-1 | FeaturesServiceImpl | 8 - org.apache.karaf.features.core - 4.1.5 | Changes to perform:
2018-07-04T12:25:01,237 | INFO | features-1-thread-1 | FeaturesServiceImpl | 8 - org.apache.karaf.features.core - 4.1.5 | Region: root
2018-07-04T12:25:01,237 | INFO | features-1-thread-1 | FeaturesServiceImpl | 8 - org.apache.karaf.features.core - 4.1.5 | Bundles to install:
2018-07-04T12:25:01,237 | INFO | features-1-thread-1 | FeaturesServiceImpl | 8 - org.apache.karaf.features.core - 4.1.5 | mvn:com.sun.jersey/je

Strange.  Even in the normal run it took 6s before "Adding features..." was logged. What is it doing during that period....  maybe adding feature repos, installing boot features...  we'd need a thread dump (or several) during that period to get an idea.  Does CSIT configure the org.ops4j.pax.url.mvn.cfg to only use the local system dir or does it allow external resolution of artifacts? I'm wondering if it's trying to download artifact(s) over the network.

I'm lowering the priority on this issue. This is very sporadic and difficult to reproduce.

I do have a patch that should detect when this issue occurs, and do a thread dump:

https://git.opendaylight.org/gerrit/#/c/73667/

my local docker container running ODL seems to be stuck in this state. I'm not sure what to do, but I don't want to get out of this state without at least trying to figure out some clues. anyone with ideas, please pass them my way.

btw, I'm just now realizing that we are not the only place this kind of thing is seen:

https://stackoverflow.com/questions/50734332/karaf-does-not-start
http://karaf.922171.n3.nabble.com/Karaf-4-0-0-6-lines-in-the-logfile-and-nothing-more-td4041410.html

In this state can you use fuser to know the user of /tmp/karaf-0.8.3-SNAPSHOT/lock?

fuser -v /tmp/karaf-0.8.3-SNAPSHOT/lock

Just to see if this is a file lock problem.

yeah, user seems fine:

with karaf stopped:

$ pwd
/home/jluhrsen/jamo/repos/OpenDaylight/netvirt-ha-docker/mounts/1/assembly
$ sudo fuser lock

starting karaf:

sudo fuser lock
/home/jluhrsen/jamo/repos/OpenDaylight/netvirt-ha-docker/mounts/1/assembly/lock: 15756
ps -elf | rg 15756
0 S root     15756 15585 99  80   0 - 2038025 -    15:52 pts/5    00:04:17 /usr/bin/java -Djava.security.properties=/odlha/karaf/target/assembly/etc/odl.java.security -Xms128M -Xmx2048m -XX:+UnlockDiagnosticVMOptions -XX:+HeapDumpOnOutOfMemoryError -Dcom.sun.management.jmxremote -Djava.security.egd=file:/dev/./urandom -Djava.endorsed.dirs=/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.172-9.b11.fc28.x86_64/jre/jre/lib/endorsed:/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.172-9.b11.fc28.x86_64/jre/lib/endorsed:/odlha/karaf/target/assembly/lib/endorsed -Djava.ext.dirs=/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.172-9.b11.fc28.x86_64/jre/jre/lib/ext:/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.172-9.b11.fc28.x86_64/jre/lib/ext:/odlha/karaf/target/assembly/lib/ext -Dkaraf.instances=/odlha/karaf/target/assembly/instances -Dkaraf.home=/odlha/karaf/target/assembly -Dkaraf.base=/odlha/karaf/target/assembly -Dkaraf.data=/odlha/karaf/target/assembly/data -Dkaraf.etc=/odlha/karaf/target/assembly/etc -Dkaraf.restart.jvm.supported=true -Djava.io.tmpdir=/odlha/karaf/target/assembly/data/tmp -Djava.util.logging.config.file=/odlha/karaf/target/assembly/etc/java.util.logging.properties -Dkaraf.startLocalConsole=true -Dkaraf.startRemoteShell=true -classpath /odlha/karaf/target/assembly/lib/boot/org.apache.karaf.diagnostic.boot-4.1.5.jar:/odlha/karaf/target/assembly/lib/boot/org.apache.karaf.jaas.boot-4.1.5.jar:/odlha/karaf/target/assembly/lib/boot/org.apache.karaf.main-4.1.5.jar:/odlha/karaf/target/assembly/lib/boot/org.osgi.core-6.0.0.jar org.apache.karaf.main.Main

cat karaf.log
Jul 24, 2018 10:21:47 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /odlha/karaf/target/assembly/lock
Jul 24, 2018 10:21:47 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 24, 2018 10:21:47 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100
Jul 24, 2018 10:34:45 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /odlha/karaf/target/assembly/lock
Jul 24, 2018 10:34:45 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 24, 2018 10:34:45 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100
Jul 24, 2018 10:37:19 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /odlha/karaf/target/assembly/lock
Jul 24, 2018 10:37:19 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 24, 2018 10:37:19 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100
Jul 24, 2018 10:52:11 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /odlha/karaf/target/assembly/lock
Jul 24, 2018 10:52:11 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 24, 2018 10:52:11 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100

since my reproduction is in a docker container, I'm able to start the container and then bounce karaf as needed.

Every time I bounce it I get the same little lockAquired messages in karaf.log, but that's it.

However, it seems it's still loading the karaf features and maybe working fine. I see that port 6653 (openflow)
gets lit up when I start karaf.

It's still a mystery why the karaf.log is not having any output. The karaf shell "log:display" is also empty.

I did see one stdout error when starting the karaf shell, but no idea if it's related at all. here it is:

opendaylight-user@root>23:42:39.944 [Blueprint Extender: 2] ERROR org.opendaylight.netvirt.vpnmanager.LearntVpnVipToPortEventProcessor - Failed to register the entity arpmonitoring

One thing to try that may give us some clues, is strace.

strace -p <karaf.pid>

can't do this in my current setup. docker security stops me. I can maybe start a new container with flags to
allow it, but then I'm worried that this problem will go away.

It turns out this is caused by the Pax Logging configuration file having the wrong contents, so the logs aren’t stored in the Karaf log file. Jamo reproduced this, and had a configuration file which only contained the lines from qosservice.cfg. So it seems that QosAlertGenerator in NetVirt is involved — it rewrites the configuration file...

When this happens, the container itself is functional. That explains the seven minute thing: the container started, with no Pax logging (so only the initial lines made it), but the container worked so CSIT continued, ended up killing Karaf and starting it again. There is no double-start causing locking issues, it’s two Karaf instances being started in succession but with no logging.

nice find. I assume it's getting overwritten with log4j settings instead of log4j2.

yeah, this is starting to explain a lot of seeming weirdness. It explains why I couldn't figure out my logs and timestamps when
working on CONTROLLER-1849. At some point my node hit this bug and my automation looped 31 times looking for 1849
but no logs came. So, when I finally hit the bug, there was nothing to see and pass on.

We (skitt, thapar and I) saw a corrupted logging config file when I started karaf and then quickly exited with a CTRL-C.

So we have something troublesome that can pop up if we stop (kill -9, CTRL-C, maybe other ways) a node at the wrong time.

I'll see if I can find a more reliable way to reproduce this, if someone can think of a safer way to have netvirt rewrite this logging
configuration file.

ok, I can reproduce this locally. The bottom line, I think, is if we kill the karaf process at some perfect time, the
logging config file gets hosed. I don't know how to recover it either, other than having a good copy nearby, which
I can get from the odlparent repo. That copy will have 91 lines in it. After netvirt is started and makes it's qos
additions, it will have 107 lines in it.

My most recent reproduction saw that the log file was completely empty, but I've seen it in various truncated
forms as well.

this bash script can be used for reproduction. Just replace the ${LOCATION} env var with the root of where you want
it to start karaf and find the logging config file:

#!/bin/bash

while true
do
  # start karaf
  ${LOCATION}/karaf/target/assembly/bin/start

  # pick a random value between 1-15 seconds for when we kill karaf
  sleepy_time=$((RANDOM % (40 - 20 + 1) + 20))
  echo "Waiting $sleepy_time seconds before killing karaf"
  sleep $sleepy_time
  # kill it
  ps aux | grep karaf.main | grep -v grep | awk '{print "kill -9",$2}' | sh

  # check line count is right in logging config file 
  linecount=`cat ${LOCATION}/karaf/target/assembly/etc/org.ops4j.pax.logging.cfg | wc -l`

  if [ "$linecount" -ne "107" ]; then
          echo "might have caught the mysterious config file corruption monster"; exit 1
  fi

done

It seems odd for QosAlertGenerator to add fixed logging configuration in code at runtime, usually such configuration is set up on deployment if desired. I don't know the history of this but perhaps we should consider removing it.

yeah. or can there be a more atomic way to modify the file such that a badly timed kill won't cause this?

That's the risk/danger of killing any process - could leave something in a corrupted state. The levelDB files could get corrupted if it was in the middle of updating a table...

of course. and a power outage, OOM crash, kernel panic...

You could try deleting the etc/org.opendaylight.netvirt.qosservice.fcg file for your testing if this issue is blocking it. However looking at QosAlertGenerator it looks it would blow up with an NPE if the file doesn't exist but I can push a quick patch for that.

ok, what's the theory here? without that file, there will be no actual attempt to modify that logging config file, so we won't have the chance of getting a corrupted file at all?

Not sure if an NPE will hurt me will it? not in the case where I'm trying to reproduce the CONTROLLER-1849 restart
issue.

The qos service bundle would bomb out and fail to start - you don't care about that for your testing but it could affect the diag status checks. For your testing I would suggest to not install integration-all - all you need is the odl-clustering-test-app (ie cars/people)

yes. good point. I got ahead of myself here, but at least we found some answers to some mysteries.

back to CONTROLLER-1849 without netvirt features. Really hoping someone will be able to address
this one though.

Given that this isn't a clustering problems but Netvirt bug moved to Sam.

https://lists.opendaylight.org/pipermail/netvirt-dev/2018-July/007293.html

https://git.opendaylight.org/gerrit/#/c/74496/

NETVIRT-1386 opened to track discussing if and how a better solution can be re-implemented in a future follow up change to the c/74496 short term removal of the code that modified the logging configuration.